Abnormal CPU utilization for stopwatch

[danlkv]

Hello

I noticed that when I use stopwatch / clock mode, termdown loads CPU almost to 100%. This is not how a simple stopwatch should behave. Timer mode is fine.

Below see some profiling data obtained using perf tool for stopwatch, timer and bash sleep function.
Note the task-clock and CPU clock frequency. The difference is also noticable for cooler fan noise.

⟩ perf stat termdown -z

 Performance counter stats for 'termdown -z':

          14274.19 msec task-clock:u              #    0.855 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
              3777      page-faults:u             #    0.265 K/sec
       42938581915      cycles:u                  #    3.008 GHz
       67333349803      instructions:u            #    1.57  insn per cycle
       10616874674      branches:u                #  743.781 M/sec
          83548787      branch-misses:u           #    0.79% of all branches

      16.686076853 seconds time elapsed

      13.758134000 seconds user
       0.515512000 seconds sys


⟩ perf stat sleep 5

 Performance counter stats for 'sleep 5':

              3.34 msec task-clock:u              #    0.001 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
                58      page-faults:u             #    0.017 M/sec
            344081      cycles:u                  #    0.103 GHz
            240960      instructions:u            #    0.70  insn per cycle
             53836      branches:u                #   16.137 M/sec
              4084      branch-misses:u           #    7.59% of all branches

       5.009497461 seconds time elapsed

       0.000000000 seconds user
       0.005746000 seconds sys


⟩ perf stat termdown 5

 Performance counter stats for 'termdown 5':

            450.24 msec task-clock:u              #    0.084 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
              3775      page-faults:u             #    0.008 M/sec
         823480722      cycles:u                  #    1.829 GHz
        1074623603      instructions:u            #    1.30  insn per cycle
         220645709      branches:u                #  490.064 M/sec
           5177317      branch-misses:u           #    2.35% of all branches

       5.358574635 seconds time elapsed

       0.343564000 seconds user
       0.112419000 seconds sys

I managed to fix it by putting sleep(.2) in while loop in stopwatch. I'm not sure this is the right way to mitigate the problem, though.

Here're the stats for the modified termdown installed from source:

⟩ perf stat termdown -z

 Performance counter stats for 'termdown -z':

            685.45 msec task-clock:u              #    0.074 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
              6648      page-faults:u             #    0.010 M/sec
         896813441      cycles:u                  #    1.308 GHz
        1270088395      instructions:u            #    1.42  insn per cycle
         253694359      branches:u                #  370.114 M/sec
           5930235      branch-misses:u           #    2.34% of all branches

       9.240416002 seconds time elapsed

       0.561054000 seconds user
       0.136016000 seconds sys

My system:

⟩ termdown --version
1.17.0
⟩ python -V
Python 3.8.3
⟩ uname -a
Linux archlinux 5.6.15-arch1-1 #1 SMP PREEMPT Wed, 27 May 2020 23:42:26 +0000 x86_64 GNU/Linux

[dther]

I think using sleep in the while loop is a reasonable solution, it seems it's used already for a similar purpose in input_thread_body. If you don't mind, I might write a pull request later today.

[trehn]

Apparently this only happens with -z and goes away if I just remove

            if time:
                sleep_target = sleep_target.replace(microsecond=0)

Will need to investigate more. We probably end up sleeping for zero seconds for a number of iterations each second, depending on when within a second we started the program, hence the wildly varying amount of CPU utilization:

> time termdown -zq 10
10.010	10	total

real	0m10.143s
user	0m1.772s
sys	0m0.041s

> time termdown -zq 10
10.011	10	total

real	0m10.132s
user	0m8.829s
sys	0m0.068s

> time termdown -zq 10
10.011	10	total

real	0m10.136s
user	0m6.246s
sys	0m0.072s