Unit test "t/02-call.t" hangs for 40 seconds with recent versions of libgrpc

[laustbn]

I noticed this while building the library on Debian Bookworm. The test t/02-call.t consistently takes 40 seconds to complete with recent versions of the gRPC library. It seems to get stuck during the first sub-test. It still passes eventually and other tests are quick. Is this expected?

Steps to reproduce:

apt -y install git build-essential libgrpc-dev libdevel-checklib-perl
git clone https://github.com/joyrex2001/grpc-perl
cd grpc-perl
perl Makefile.PL
make
make test

Output (look at wallclock secs)

Debian Buster (libgrpc 1.16.1-1)

root@grpc-test-buster:~/grpc-perl# PERL_DL_NONLAZY=1 "/usr/bin/perl" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(0, 'blib/lib', 'blib/arch')" t/02-call.t
t/02-call.t .. ok
All tests successful.
Files=1, Tests=15,  0 wallclock secs ( 0.01 usr  0.00 sys +  0.02 cusr  0.01 csys =  0.04 CPU)
Result: PASS

Bullseye (libgrpc 1.30.2-3)

root@grpc-test-bullseye:~/grpc-perl# PERL_DL_NONLAZY=1 "/usr/bin/perl" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(0, 'blib/lib', 'blib/arch')" t/02-call.t
t/02-call.t .. ok
All tests successful.
Files=1, Tests=15,  0 wallclock secs ( 0.01 usr  0.00 sys +  0.03 cusr  0.00 csys =  0.04 CPU)
Result: PASS

Bookworm (libgrpc 1.51.1-3+b1)

root@grpc-test-bookworm:~/grpc-perl# PERL_DL_NONLAZY=1 "/usr/bin/perl" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(0, 'blib/lib', 'blib/arch')" t/02-call.t
t/02-call.t .. ok
All tests successful.
Files=1, Tests=15, 40 wallclock secs ( 0.01 usr  0.00 sys +  0.04 cusr  0.01 csys =  0.06 CPU)
Result: PASS

I also built v1.45.3 from source, both to try an intermediate version and to get debug symbols. It had the same behavior. I captured a stack trace from that version showing where it gets stuck:

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f0ccc369c66 in epoll_wait (epfd=4, events=0x7f0ccbd2d064 <g_epoll_set+4>, maxevents=100, timeout=-1)
    at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30	../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
(gdb) bt
#0  0x00007f0ccc369c66 in epoll_wait (epfd=4, events=0x7f0ccbd2d064 <g_epoll_set+4>, maxevents=100, timeout=-1)
    at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x00007f0ccb89aafd in do_epoll_wait(grpc_pollset*, grpc_core::Timestamp) () from /root/local/lib/libgrpc.so.23
#2  0x00007f0ccb89bb22 in pollset_work(grpc_pollset*, grpc_pollset_worker**, grpc_core::Timestamp) () from /root/local/lib/libgrpc.so.23
#3  0x00007f0ccb8a7b0d in pollset_work(grpc_pollset*, grpc_pollset_worker**, grpc_core::Timestamp) () from /root/local/lib/libgrpc.so.23
#4  0x00007f0ccb8ae0a5 in grpc_pollset_work(grpc_pollset*, grpc_pollset_worker**, grpc_core::Timestamp) ()
   from /root/local/lib/libgrpc.so.23
#5  0x00007f0ccb97f92f in cq_pluck(grpc_completion_queue*, void*, gpr_timespec, void*) () from /root/local/lib/libgrpc.so.23
#6  0x00007f0ccb97fc0d in grpc_completion_queue_pluck () from /root/local/lib/libgrpc.so.23
#7  0x00007f0ccc1649bd in XS_Grpc__XS__Call_startBatch () from /root/grpc-perl/blib/arch/auto/Grpc/XS/XS.so
#8  0x00005644e8257f18 in Perl_pp_entersub (my_perl=0x5644e889f2a0) at ./build-static/pp_hot.c:5357
#9  0x00005644e824def6 in Perl_runops_standard (my_perl=0x5644e889f2a0) at ./build-static/run.c:41
#10 0x00005644e81ac779 in S_run_body (oldscope=<optimized out>, my_perl=<optimized out>) at ./build-static/perl.c:2721
#11 perl_run (my_perl=0x5644e889f2a0) at ./build-static/perl.c:2644
#12 0x00005644e817e4b2 in main (argc=<optimized out>, argv=<optimized out>, env=<optimized out>) at ./build-static/perlmain.c:110

I wonder if the 40 seconds are some kind of internal timeout in the eventloop inside libgrpc?

I originally wanted to test against all older releases of libgrpc, to learn when the regression was introduced, but ran into compilation issues with Abseil (one of the dependencies) and gave up for the time being.