So I have this service application which is ported from a Windows Delphi 2007 TService app to a regular command line program for use in Linux. It runs on a RaspberryPi3B+

Normally it sits idle doing nothing but waiting for a client to connect via TCP or a time to occur when it needs to execute a task. Or else for system signals from systemd.

So in the main program there is a loop after the initialization has been done looking like this:

  While not (bSTerm or bSInt or bsHup) do //System exit signals
  begin
    //Here is where the server runs as defined elsewhere
    //Eternal loop to wait for system messages
    CheckSynchronize(5); //Timeout here instead of using sleep
    if CheckRestartReq then //Check if we need to restart the service
    begin
      Debug_Writeln('Restart timeout reached - exiting');
      FLogServ.StdLog('Restart timeout reached - exiting');
      break;
    end;
  end;

The actual stuff that is done happens inside the objects that get created before reaching this loop and they are the following events:

If a TCP connection is made from a client a number of handler objects are created and started for the client communications. These are done using Indy. But if there is no client connection the objects do not exist.

On a timer timeout a check is made if there are any programmed tasks waiting for execution. These can be scheduled on minute resolution times. If there is no waiting task then nothing happens.

In this scenario I expected next to no CPU usage when this is running as a service controlled by systemd, but in fact top shows the service to consume 10% CPU when it is doing nothing, no client connected and no task running...

How can I find out what is the cause of this?

I am developing using Lazarus 2.0.12 and FPC 3.2.0 on the RPi3B+.

I found the LazProfiler on the wiki: https://wiki.freepascal.org/LazProfiler

Could it be used to profile a service command line application (no GUI) too or is it limited to "normal" GUI type applications?

Does it work on ARM Linux?

https://forum.lazarus.freepascal.org/index.php/topic,38983.msg420564.html#msg420564

My program in Lazarus *is* a "simple program" and it has no GUI components.

I never even looked at the implementation of CheckSynchronize()... It was just given in another thread when I was working on the port from Delphi to Linux and thus from the Windows GUI environment to the non-GUI command line program environment.

It was needed in the main loop in order for threads down inside the program to be able to transfer their data into an event handler which is processing incoming data.

Originally I had a sleep(5) inside the loop too, but I took that out when it was clear that CheckSynchronize had a timeout argument (optional).

It is now close to midnight so I have to postpone any testing until tomorrow.

The name 'Gui thread' is misleading. It's simply the main program thread.

If you want to use TThread.Synchronize then the call to CheckSynchronize is needed. The LCL for GUI application simply calls it automatically for you. In a non-GUI command-line program, you're responsible for calling it from time to time.

Michael.

I don't know if it's related, but I experienced a similar problem a few years ago.

It's a console dll written in Freepascal and compiled for Win64 and Linux (Ubuntu). It uses several threads and uses CheckSynchronize to make calls in the main thread.

The dll is loaded and used by a 4gl program (www.4js.com), I think the 4gl runtime is compiled with Visual C++ on Windows and GNU C++ on Linux.

With recent (a few years ago) Freepascal a similar CPU consumption when idle appeared, but only in Windows, not in Linux.

I didn't needed recent functionalities of Freepascal, so a dirty workaround for me for this project was to stick to Lazarus 1.6 / 2016 02 14 / FPC 3.0.0 / SVN 51360 (from menu Help/About Lazarus). I don't have the CPU consumption with this version.

That is what I had learned back in beginning of this year when I was starting testing on actual hardware. Checksynchronize is needed in the main program loop in order for threads to fire off events etc. I use threads to handle serial port communications, and the threads should be disposed of after use...

Now I have done some more investigations and I am more confused by it... My service program runs at about 4% CPU usage as shown by top. This holds true for a long time after starting it (several idle days).

But when a client connects to inspect data on the system the usage spikes when he commands some data display etc. But then goes back to the 4% or so.

If the client enables a task to be executed then nothing really happens until that task starts on its set time.
At that time the CPU usage raises from 4% to 11% and goes up/down a few % for the minutes it runs and then returns to an idle value of about 8%, which it never gets below after that.

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.

Michael.

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....

It looks like your application is spawning additional processes. If it's supposed to do that, then all is well.  If it isn't supposed to do that when it's idling, then you have some troubleshooting to do. :)

I found a howto-page for strace so I could modify the call to have strace produce a summary after running for the set time (3 seconds here). Easier read but does not give me much to work with.

timeout --signal=2 3s strace -f -c -p 488 -o tracelog2.log

% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 46.47 0.348353 414 841 nanosleep 27.67 0.207437 17286 12 _newselect 16.17 0.121220 211 572 77 futex 2.54 0.019020 89 213 munmap 1.77 0.013281 62 213 mmap2 1.63 0.012250 43 284 284 ioctl 0.73 0.005485 77 71 madvise 0.55 0.004137 29 142 gettimeofday 0.53 0.003958 27 142 clock_gettime 0.51 0.003858 54 71 rt_sigprocmask 0.37 0.002748 38 71 clone 0.36 0.002688 37 71 sched_setscheduler 0.31 0.002315 32 71 set_robust_list 0.30 0.002262 31 71 ugetrlimit 0.07 0.000548 182 3 1 restart_syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.749560 2848 362 total

I don't really see how this helps either, though....

As a reminder here is the main application's loop:

      While not (bSTerm or bSInt or bsHup) do
      begin
        //Here is where the server runs as defined elsewhere
        //Eternal loop to wait for system messages
        Sleep(5); //To not hog the CPU
        CheckSynchronize(); //No timeout here since sleep is used
        //CheckSynchronize(5); //Timeout here instead of using sleep
        if CheckRestartReq then
        begin
          Debug_Writeln('Restart timeout reached - exiting');
          FLogServ.StdLog('Restart timeout reached - exiting');
          break;
          //FServerStartTick := GetTickCount64; //Reset timeout for now
        end;
      end;

And CheckRestartReq implementation:
Note that FRemoteTaskServer.AutoRestartInterval is 0 here. So the function CheckRestartReq should always return immediately with a false result.

function CheckRestartReq: boolean;
var
  NextStart: TDateTime;
begin
  Result := false;
  if FRemoteTaskServer.AutoRestartInterval < 120 then exit; //Not configured for
automatic restart (min time 2 min)
  if (GetTickCount64 - FServerStartTick) <
(FRemoteTaskServer.AutoRestartInterval * 1000) then exit; //Not reached set
restart time yet
  if FRemoteTaskServer.TaskRunning then exit; //Cannot restart when task is
running
  if FSuperStingSocketServer.ClientCount > 0 then exit; //Cannot restart when
client connected
  NextStart := FRemoteTaskServer.NextTaskStartTime; //Get next time a task will
start
  if NextStart = 0 then  //No task scheduled to start so OK to restart server
  begin
    Result := true;
    exit;
  end;
  if (NextStart - Now) > (2.0 / 60 / 24) then  Result := true; // More than 2
minutes until next task start, so OK to exit
end;

So 90.3 % of the time is spent in these 3 syscalls...

Does this mean that:
_newselect is running for 207 ms during the 3 second test time? (Which is 17 ms per call)

And what is _newselect in the first place?

I assume nanosleep is some kind of Linux API call made by fpc when it invokes sleep() in my code.

And futex????

Select (or _newselect) checks if there is activity on a file descriptor. If you're working with Indy, it uses this call to check for data on a socket; It is called frequently.

I assume nanosleep is some kind of Linux API call made by fpc when it invokes sleep() in my code.

Yes.

And futex????

Futex is used for thread synchronisation.
Again, if you're using Indy and threads, it is called a lot.

Michael.

You are right concerning Indy usage!
This is what is used for the networking part. The application has been ported from Delphi on Windows where it was a TService based application.

I will have to look at what is going on with the permanent increase in activity during (expected) and after a task execution (should go back to idle).

But I will have to do a couple of more checks where I make it start a task and while the task executes run the strace -c recording.

Some objects might not be freed properly or else do not get down to idle activity...

The code is quite big and handles several separate aspects, like client communication via TCP/IP socket, scheduling the tasks, running a task and collecting the output data, mailing the result data to configured recipients.

My test done with strace was done after I have communicated with the application as a client.
I really need to test this:
- right after the service restart
- during a client communication session
- after disconnecting a client
- after switching on scheduling
- during a task execution
- after task execution

So there will be a lot of data gathering to see what changes, but since I did not know about strace and it seems able to do this it might actually work.

Thanks for pointing me towards it!

Bo Berglund wrote

The question is: how to find what is still using CPU?

Have a look at the tool sysprof. This is a statistical sampling profiler that can show you a call tree with percentages of CPU consumption. Thee are also other sampling profilers around (oprofile, perf/hotspot, google-gperftools, etc..) that all work by the same principle, you could try which one suits you best. They should all be able to tell you where exactly it spends how much of its CPU time. You don't need to instrument the code, just compile it with dwarf debug info contained in the executable (not as external debug file), maybe also reduce the optimization level if, and it should be able to show you the call tree along with time consumption of each function.

Bernd

In the end we have a black box with Indy that isn't going to be opened.. and from the sound of it, a dated method of manually checking for i/o (in this case likely with select() and a zero timeout..). Calling that and sleep() over and over millions of times..

I'm sorry to the OP if I'm assuming a lot but my guess is the code is a bit old and could use some refactoring to do away with the old Pascal "active loop."

Yes it is *old* code written with Delphi starting from about 2004 and "maintained" on Windows up until 2012 or thereabouts.

Issues were discovered on Windows7 but these were fixed and then Windows 10 made it so much worse that I decided to try and port it over to Linux.

It is a Windows TService application ported to a command line program on Linux so the base framework had to be modified a lot...
But the majority of the code is only modified wherever it deals with protection dongles and read/write the Windows Registry.
Plus all file system accesses using \ separators and drive letters... And of course the event driven model as a whole...

As long as it does not eat up more than 10% or so CPU I might have to swallow it. And maybe schedule a regular restart of the server to clear whatever builds up.