0

My HTTP application suddenly started taking extra time to start up. During this phase, it loads the data from the disk to the in-memory data structure.

I doubt it is due to the extensive logging inside loop in the last change but I want some proof to be sure that the bottleneck is IO.

I did strace which shows too many sys write calls as expected, printing the first few lines of it here.

ubuntu@hemu-mcahine:~$ sudo strace -p 109374
[sudo] password for ubuntu:
strace: Process 109374 attached
write(1, "s1 size:, %!i(int=338632)\n", 26) = 26
futex(0x93a7d8, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xc00003c948, FUTEX_WAKE_PRIVATE, 1) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=109374, si_uid=1001} ---
rt_sigreturn({mask=[]})                 = 1
write(1, "s1 size:, %!i(int=338633)\n", 26) = 26
write(1, "s1 size:, %!i(int=338634)\n", 26) = 26
write(1, "s1 size:, %!i(int=338635)\n", 26) = 26
write(1, "s1 size:, %!i(int=338636)\n", 26) = 26
write(1, "s1 size:, %!i(int=338637)\n", 26) = 26
write(1, "s1 size:, %!i(int=338638)\n", 26) = 26
write(1, "s1 size:, %!i(int=338639)\n", 26) = 26
write(1, "s1 size:, %!i(int=338640)\n", 26) = 26
write(1, "s1 size:, %!i(int=338641)\n", 26) = 26
write(1, "s1 size:, %!i(int=338642)\n", 26) = 26
write(1, "s1 size:, %!i(int=338643)\n", 26) = 26
write(1, "s1 size:, %!i(int=338644)\n", 26) = 26
write(1, "s1 size:, %!i(int=338645)\n", 26) = 26
write(1, "s1 size:, %!i(int=338646)\n", 26) = 26
write(1, "s1 size:, %!i(int=338647)\n", 26) = 26
write(1, "s1 size:, %!i(int=338648)\n", 26) = 26
write(1, "s1 size:, %!i(int=338649)\n", 26) = 26
...

I was expecting to see a high "%wa" as the output of "top" but it mostly shows both CPUs as idle without any significant waiting or compute time, Why it is so?

Here is the output of the top, first process indicates my application

top - 08:21:58 up 5 days, 21:32,  2 users,  load average: 0.00, 0.00, 0.00
Tasks: 140 total,   1 running, 138 sleeping,   0 stopped,   1 zombie
%Cpu0  :  0.3 us,  1.3 sy,  0.0 ni, 98.0 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu1  :  0.7 us,  1.0 sy,  0.0 ni, 98.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3925.3 total,   2310.1 free,    831.4 used,    783.9 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2861.2 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 109374 ubuntu    20   0 1084416 118780   5392 S   1.7   3.0   0:01.77 server
 108671 ubuntu    20   0   14836   7020   4304 S   0.7   0.2   0:06.71 sshd
    841 root      20   0  402468  30328   8916 S   0.3   0.8   6:07.89 python3
  86001 root      20   0       0      0      0 I   0.3   0.0   0:06.41 kworker/0:3-events
  88908 ubuntu    20   0 1029916  77444  33692 S   0.3   1.9   0:39.35 node
 109196 root      20   0       0      0      0 I   0.3   0.0   0:00.74 kworker/u4:0-events_unbound
 109280 root      20   0       0      0      0 I   0.3   0.0   0:00.44 kworker/u4:1-events_power_efficient
 109398 ubuntu    20   0   11276   4224   3548 R   0.3   0.1   0:00.01 top
      1 root      20   0  168972  13052   8312 S   0.0   0.3   0:15.16 systemd
      2 root      20   0       0      0      0 S   0.0   0.0   0:00.04 kthreadd
      3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp
      4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp
      5 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 netns
      7 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/0:0H-events_highpri
      9 root       0 -20       0      0      0 I   0.0   0.0   0:08.76 kworker/0:1H-events_highpri
     10 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mm_percpu_wq
     11 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_rude_
     12 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_trace
     13 root      20   0       0      0      0 S   0.0   0.0   0:00.77 ksoftirqd/0
     14 root      20   0       0      0      0 I   0.0   0.0   0:33.30 rcu_sched
     15 root      rt   0       0      0      0 S   0.0   0.0   0:02.53 migration/0

How to know the reason behind high idle time and why isn't "%wa" too much when my code is continuously logging and making the sever slow?

4
  • The write() calls that are listed in your strace command are writes to file descriptor 1, which is nearly always standard output (commonly called "stdout"). Are these writes actually being directed to a file on disk, or are they being redirected to /dev/null? If they're redirected to /dev/null, there's no I/O wait involved as the writes are merely discarded.
    – Sotto Voce
    Sep 28, 2022 at 15:32
  • I am logging it to the terminal by default so write() to fd 1 is expected. Isn't logging to the terminal also a disk IO?
    – shubmishra
    Sep 28, 2022 at 15:51
  • 1
    In the majority of use cases, writing to the terminal window does not write to disk, and I would not expect it to show a detectable increase in i/o wait metrics. Have you tried redirecting the application's stdout to /dev/null to see if that has any effect on the app's startup time? If it doesn't, then you can move on to investigating other potential sources of slowness.
    – Sotto Voce
    Sep 28, 2022 at 16:06
  • you are right, I tested with disk they turn out to be much faster than consoling to terminal.
    – shubmishra
    Sep 29, 2022 at 6:17

1 Answer 1

1

I experimented a little bit on some scenarios and I think now I have my answers -

After @Sotto's comment and some googling, I find out printing to the terminal is not the same as writing to disk as the former requires extra processing, thread needs to wait until data prints to terminal and buffering works differently for the terminal than for disk I/O. This answer explains it pretty well https://stackoverflow.com/questions/6338812/printing-to-the-console-vs-writing-to-a-file-speed.

furethermore, directing logs to the file instead of stdout is faster but lead to increase kernel space time sy not the wa% as per Top command. I found this is because write sys call does not directly writes to file in disk but send it to file system's buffer which further takes care to write to disk optimally.

Later I started printing all logs with sync sys call to clear buffer and instantly commits all data to file, here I saw signifantly high wa% as expected in IO operations and CPU was mostly sleeping.

Conclusion:

  • Terminal is not same as disk I/O, it is even slower.
  • I/O functions written over write syscall are not neccessarily add disk writting overhead due to File system's buffer but they do add context switch and consume cpu cycles in kernel space

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .