[fpc-pascal] My Linux service application consumes 10% CPU when idling - why?

[Bo Berglund]

On Fri, 8 Oct 2021 00:12:50 +0200 (CEST), Michael Van Canneyt via fpc-pascal
<fpc-pascal at lists.freepascal.org> wrote:

>> No matter how long I wait it is now stuck at that double value.
>>
>> So clearly something must be left behind after the task has finished...
>>
>> The question is: how to find what is still using CPU?
>
>Run the process under strace:
>strace -f -p PID -o log1.txt
>with PID the process ID.
>
>You will see what system calls are executed. Do this when the load is 4% and
>when it's 8%, maybe this will tell you something.
>

Sorry for not getting back until now, but I have been dealing with Linux system
upgrades the whole week...

So I tried this at an idle time after start on the test system when nothing has
happened and top shows 4% CPU usage. PID of the application is 488.

strace -f -p 488 -o tracelog1.log

It resulted in a massive tracelog1.log logfile with stuff like this (cut at
random iside the file):

488   <... nanosleep resumed> 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000}, 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000},  <unfinished ...>
533   <... nanosleep resumed> 0x76212bb0) = 0
533   nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
488   <... nanosleep resumed> 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000}, 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000},  <unfinished ...>
533   <... nanosleep resumed> 0x76212bb0) = 0
533   nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
488   <... nanosleep resumed> 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000},  <unfinished ...>
533   <... nanosleep resumed> 0x76212bb0) = 0
533   nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
488   <... nanosleep resumed> 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000}, 0x7ee339f0) = 0
488   nanosleep({tv_sec=0, tv_nsec=5000000},  <unfinished ...>
6063  <... futex resumed> )             = -1 ETIMEDOUT (Connection timed out)
6063  futex(0x76f6fb98, FUTEX_WAKE_PRIVATE, 1) = 0
6063  mmap2(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x75e0b000
6063  futex(0x75e0b048, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
533   <... nanosleep resumed> 0x76212bb0) = 0
533   nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
488   <... nanosleep resumed> 0x7ee339f0) = 0
488   clone( <unfinished ...>
6064  set_robust_list(0x75aff4b0, 12)   = 0
6064  futex(0x75aff654, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
488   <... clone resumed> child_stack=0x75afef78,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CL$
488   sched_setscheduler(6064, SCHED_OTHER, [0]) = 0
488   futex(0x75aff654, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
6064  <... futex resumed> )             = 0
488   <... futex resumed> )             = 1
6064  futex(0x75aff654, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
488   clock_gettime(CLOCK_MONOTONIC_RAW,  <unfinished ...>
6064  <... futex resumed> )             = 0
488   <... clock_gettime resumed> {tv_sec=228720, tv_nsec=105079052}) = 0

which I really understand nothing of...

Running for some 5-10 secnds resulted in a logfile of 2 MB size

Meanwhile the strace outputs stuff like this to the screen:

strace: Process 6360 attached
strace: Process 6361 attached
strace: Process 6362 attached
strace: Process 6363 attached
strace: Process 6364 attached
strace: Process 6365 attached
strace: Process 6366 attached
strace: Process 6367 attached
strace: Process 6368 attached
strace: Process 6369 attached
strace: Process 6370 attached
strace: Process 6371 attached
strace: Process 6372 attached

I don't understand what this means either....


-- 
Bo Berglund
Developer in Sweden