Signal delivery time

[Marc Lehmann]

On Tue, Feb 09, 2021 at 02:31:46PM -0500, Steve Grubb <sgrubb at redhat.com> wrote:
> Hello,

Hi, sorry for the late reply.

> There is something that I am puzzling over. I am measuring the time from when 
> a signal arrives until it gets delivered to the handler function using 
> ltrace.

Well, libev can only call your callback when it is on control. Are you
sure you are not doing anything else?

Also, something is fishy with your ltrace (e.g. clock_gettime only has two
arguments, not four).

It's probably easier to see whats going on and where time is used by using
sth. like strace -tttTT, which also prints syscall times.

As for gettimeofday etc., on a modern unix, there should be only one call
to clock_gettime *on average*. If there is a lot of time between loop
runs, then libev needs to also check the realtime clock (which it does
using gettimeofday on your system).

> 1612897982.843213 <... epoll_wait resumed> )
> = 0xffffffff
> 1612897982.843330 __errno_location()

libev more or less calls epoll_wait and then checks errno. If your ltrace
is correct, this takes 0.1ms. With a 1ghz cpu, this is >100000 cycles for
what amounts to a few cpu instructions.

So I suspect something is either wrong with your measurements - for
example, ltrace slows down your program a lot (quite likely), or your
system is extremely slow (e.g. because of aggressive powersave).  Modern
cpus can take many milliseconds to wake up from sleep. Also, security
mitigations can also create enourmous overheads.

For reference, this is the output on my box, for a perl skript
(gettimeofday is not shown as it is not a kernel call here):

1613661531.647210 --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=8380, si_uid=0} ---
1613661531.647235 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000005>
1613661531.647259 rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call) <0.000005>
1613661531.647279 epoll_wait(4, [{EPOLLIN, {u32=5, u64=4294967301}}], 64, 1500001070) = 1 <0.000004>
1613661531.647301 read(5, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000004>
1613661531.647334 write(2, "Warning: something's wrong at -e"..., 41Warning: something's wrong at -e line 1.

And this is without libev:

1613661650.116256 nanosleep({tv_sec=99, tv_nsec=0}, {tv_sec=93, tv_nsec=423826822}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal) <5.576235>
1613661655.692523 --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=8380, si_uid=0} ---
1613661655.692543 rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call) <0.000004>
1613661655.692567 rt_sigprocmask(SIG_BLOCK, [QUIT], [], 8) = 0 <0.000004>
1613661655.692590 rt_sigaction(SIGQUIT, NULL, {sa_handler=0x5555556621b0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7ffff7c7d7e0}, 8) = 0 <0.000004>
1613661655.692631 write(2, "Warning: something's wrong at -e"..., 41Warning: something's wrong at -e line 1.
) = 41 <0.000005>

Libev takes 124µs, naked perl 107µs.

> If my math is correct, this is taking about 6.1 milliseconds to deliver. What 
> I'm puzzling over is why there are so many calls to gettimeofday & 
> clock_gettime?

I don't really see many calls. As written before, libev normally does one
call to clock_gettime per iteration, and some more if it needs to detect
time jumps. IF your program was alseep for a reaosnably long time, then
libev is guaranteed to take more calls.

> I do not use any timeouts or periodic timers. So, I'm 

Maybe you don't, but libev does.

> wondering why a program that has no cares about what time it is winds up 
> making so many calls about the current time?

Well, your program does care, because libev is part of it, and it "cares".

> It would appear that around 2 milliseconds of the time is spent in those
> syscalls. (This is libev 4.31.)

How did you measure this? That would be etxremely unlikely to be the
case. On my aging haswell cpu, I can do about 10 million gettimeofday
calls peer second, in perl (an interpreted language).

Maybe you do have an extreemly slow machine, but more likely it can be
explained by ltrace overhead (which is many extra syscalls) or power
saving modes.

> Also, is there a faster way to get signal delivery? I'm using the 
> ev_default_loop and only passing EVFLAG_NOENV. Any advice/insights would be 
> greatly appreciated.

You could install a signal handler directly and e.g. nanosleep. However, the
extra synchonisation, which is the main overhead of libev, will likely slow
you down to libev's level.

And I don't think libev is the reason for this indeed unnaturally long
time - likely it is something else, such as a busy cpu, ltrace overhead or
power saving.

-- 
                The choice of a       Deliantra, the free code+content MORPG
      -----==-     _GNU_              http://www.deliantra.net
      ----==-- _       generation
      ---==---(_)__  __ ____  __      Marc Lehmann
      --==---/ / _ \/ // /\ \/ /      schmorp at schmorp.de
      -=====/_/_//_/\_,_/ /_/\_\