Hi,
During writing to NVME memory I am facing unstable performance issue.
My application write pattern is 2MB block each 200msec.
In order to Isolate the root cause I wrote simple test to get write operation benchmark:
//
// Created by Yehonatans on 9/12/22.
//
#include "WriteFileBenchmark.h"
#include <fcntl.h>
#include <chrono>
#include <thread>
#include <sys/time.h>
#include <stdlib.h>
#include <cstdio>
#include <string>
class Timer {
public:
//Timer() : m_title(std::string("")), m_level(0) { };
//Timer(std::string title ) : m_title(title), m_level(0) { };
Timer(std::string title = std::string(""), int level = 0) : m_title(title), m_level(level) {}
void startTimer(void);
double getTimer(bool relative = false);
void printTimer(std::string altTitle = std::string(""), int level = -1,
bool relative = false); // relative means relative to last call to getTimer
static void setLevel(int level) { m_maxAllowedLevel = level; }
private:
struct timeval m_timerStart;
struct timeval m_timerAtLastGetTimer;
static int m_maxAllowedLevel;
std::string m_title;
int m_level;
};
int Timer::m_maxAllowedLevel = -1;
void Timer::startTimer()
{
gettimeofday(&m_timerStart, NULL);
m_timerAtLastGetTimer = m_timerStart;
}
// time elapsed in ms
double Timer::getTimer(bool relative)
{
struct timeval timerStop, timerElapsed;
gettimeofday(&timerStop, NULL);
if (relative)
timersub(&timerStop, &m_timerAtLastGetTimer, &timerElapsed);
else
timersub(&timerStop, &m_timerStart, &timerElapsed);
m_timerAtLastGetTimer = timerStop;
return timerElapsed.tv_sec*1000.0+timerElapsed.tv_usec/1000.0;
}
// print time interval in [mSec] between current time to a previous reference time (see relative)
// input: - "relative" if true, than reference time is set as last call time to getTimer(), or printTimer()
// if false, than reference time is set as last call time to startTimer()
// - level: acts as indentation. i.e. determines how many leading spaces to add before printing the timers output
void Timer::printTimer(std::string altTitle, int level, bool relative ) {
double duration = getTimer(relative);
if (level < 0) level = m_level;
if (level > m_maxAllowedLevel) return;
while(level > 0) {
printf( " "); // "/t"
level--;
}
if ( altTitle.empty() ) {
printf( "runTime: timer %s stopped after %.1f [mSec]\n",m_title.c_str(), duration ); fflush(stdout);
} else {
printf( "runTime: timer %s stopped after %.1f [mSec]\n",altTitle.c_str(), duration ); fflush(stdout);
}
}
int main()
{
m_sleepBetweenWrites = 200;
m_minFileSize = 2000000;
m_maxFileSize = 2000000;
m_nofIterations = 100000;
if(m_maxFileSize<m_minFileSize ) {
std::cout<< "m_maxFileSize<m_minFileSize"<<std::endl;
throw(camero_utils::general::InternalError("m_maxFileSize<m_minFileSize"));
}
std::string file2Create ="/mnt/Test/BM";
fd = open(file2Create.c_str(), O_RDWR | O_CREAT | O_APPEND);
// syncfs(fd);
std::vector<char>m_writeBuffer;
m_writeBuffer.resize(m_maxFileSize);;
Timer timer;
timer.startTimer();
for (auto cnt = 0u; cnt < m_nofIterations; ++cnt) {
size_t data2Write = m_minFileSize + (float)rand() / (float)RAND_MAX * (m_maxFileSize - m_minFileSize);
LOGGER(MtLogger::INFO,"write 2 file size " << data2Write << std::endl)
write(fd, (void *)m_writeBuffer.data(), data2Write);
auto time = timer.getTimer(true);
if (m_sleepBetweenWrites > time) {
std::this_thread::sleep_for(std::chrono::milliseconds(int(m_sleepBetweenWrites - time)));
}
std::cout<< "Iteration time " << time << std::endl;
}
fsync(fd);
auto time = timer.getTimer(true);
std::cout<< "Sync time " << time << std::endl;
}
This app gave me the following results:
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:31.329017] <3> : Iteration time 6.641
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:31.329247] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@56][2018-Jan-28 21:07:33.369598] <1> : m_sleepBetweenWrites time 200 2040.34
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:33.369874] <3> : Iteration time 2040.34
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:33.370015] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:33.569136] <3> : Iteration time 5.038
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:33.569432] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:33.769245] <3> : Iteration time 3.735
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:33.769506] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:33.969305] <3> : Iteration time 3.65
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:33.969573] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:34.169192] <3> : Iteration time 3.538
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:34.169494] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:34.369187] <3> : Iteration time 3.617
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:34.369493] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:34.569210] <3> : Iteration time 3.643
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:34.569388] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:34.768989] <3> : Iteration time 3.514
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:34.769116] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:34.968865] <3> : Iteration time 3.652
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:34.969026] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:35.168945] <3> : Iteration time 3.825
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:35.169089] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:35.368640] <3> : Iteration time 3.464
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:35.368795] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:35.568439] <3> : Iteration time 3.542
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:35.568572] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:35.768055] <3> : Iteration time 3.398
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:35.768185] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:35.967892] <3> : Iteration time 3.619
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:35.968023] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:36.167566] <3> : Iteration time 3.463
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:36.167727] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:36.367374] <3> : Iteration time 4.563
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:36.367538] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:36.567191] <3> : Iteration time 3.565
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:36.567339] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@56][2018-Jan-28 21:07:37.194605] <1> : m_sleepBetweenWrites time 200 627.258
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:37.194803] <3> : Iteration time 627.258
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:37.194972] <3> : write 2 file size 2000000
[WriteFileBenchmark.cpp@58][2018-Jan-28 21:07:37.394871] <3> : Iteration time 3.801
[WriteFileBenchmark.cpp@42][2018-Jan-28 21:07:37.395021] <3> : write 2 file size 2000000
The following graph shows write performance over time at mili seconds
As you can see the write latency variance is over100 times magnitude fom 4…5 msec to 627 msec.
The issue was reproduceable over few NVME types from different vendors.
Setup
Jetpack 4.5
power mode:
NV Power Mode: MODE_15W
2
How can I solve the issue because currently I am facing data drops due to RT issues which cause by long write time latency?