Satya Pawan Satya Pawan - 4 years ago 92
C Question

Latency occurs exactly after the 1st write operation to the disk. Why?

My application logs events to the log file. There's a specified threshold of 10ms. If the write operation takes more than 10ms, the event is recorded too. The application uses

fopen
and
fprintf
to write to the disk. A typical log looks like:

[4-2-2017 21:12:1] - Kernel (major) : 4
[4-2-2017 21:12:1] - WARNING : [Write latency too high 12ms]
[4-2-2017 21:12:1] - Kernel (minor) : 9
[4-2-2017 21:12:1] - CPU cores : 2
[4-2-2017 21:12:1] - CPU speed (in MHz) : 2500
[4-2-2017 21:12:1] - CPU cache : 2048
[4-2-2017 21:12:1] - CPU SIM : 0
[4-2-2017 21:12:1] - Total memory (in MBs) : 1997
[4-2-2017 21:12:1] - Free memory (in MBs) : 955
[4-2-2017 21:12:1] - Total swap (in MBs) : 974
[4-2-2017 21:12:1] - Free swap (in MBs) : 919
[4-2-2017 21:12:1] - WARNING : [LOW MEMORY]
[4-2-2017 21:12:1] - Process name : gnome-shell
[4-2-2017 21:12:1] - Filesystem : 16260798518699108994
[4-2-2017 21:12:1] - Mount : 4096


Why is there a latency exactly after the 1st write operation? No matter how many times the application runs, there is a latency exactly after the 1st operation.

Any ideas why?

Answer Source

Basing on the advices/suggestions/answers from the comments, I've done some investigation into this issue.

As Paul Ogilvie commented, the latency is indeed occurring during the 1st write, however, as log function does not support concurrency, the latency is logged after the 1st write operation is completed. Maybe it's the initialization time for the disk? Since it's an SSD, it also explains why there are no other latencies in the log file.

The latency reduced when an existing file is opened (around 8-10ms) as opposed to creating a new file and then writing to it (around 10-14ms). The excess time is used for opening the handle to the file and some of it for the kernel activity (thanks to Frankie_C for pointing it out).

EDIT: Not sure if it's a co-incidence or not, but I chose fputs over fprintf and noted down some readings and averaged 'em. Interestingly, the times seem to change depending on the function used to write to the disk.

Recommended from our users: Dynamic Network Monitoring from WhatsUp Gold from IPSwitch. Free Download