How can I tell why my Perl code is spending so much time in kernel space ("sy" in top)?

Question

When I run my program "top" reports that I am spending 30+% in "sy" (kernel space).

How can I get more information about this? What system call is eating up all this time, etc.

Thanks responders:

• It sounds like Devel::NYTProf is good for profiling the entire program -- but I had trouble installing it on Amazon Linux.

• If I just want a snapshot of system calls strace seems to be great.

Updated: I did this and the time spent in system calls is actually negligible. My best guess is the threads are stuck waiting on some resource. The answers are still good below but any advice would help.

Answer 1

You could use strace(1) - trace system calls and signals. -c flag will produce aggregate results grouped by syscall. -p NUM is a PID of running process to attach. Monitoring a crawler (for instance) looks like this:

stas@crawler2:~/ScrapMe$ strace -c -p 32184                                                                                                                                                                                              
Process 32184 attached - interrupt to quit
^CProcess 32184 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 48.00    0.000024           0       128           sendto
 26.00    0.000013           0        76           write
 26.00    0.000013           0      2652      2652 stat
  0.00    0.000000           0        24           close
  0.00    0.000000           0       226           poll
  0.00    0.000000           0        78           rt_sigaction
  0.00    0.000000           0        26           rt_sigprocmask
  0.00    0.000000           0        52           alarm
  0.00    0.000000           0        26           socket
  0.00    0.000000           0        26        26 connect
  0.00    0.000000           0        75           recvfrom
  0.00    0.000000           0        26           getsockname
  0.00    0.000000           0        26           getpeername
  0.00    0.000000           0        26           getsockopt
  0.00    0.000000           0       310           fcntl
  0.00    0.000000           0        13           epoll_wait
  0.00    0.000000           0        26           epoll_ctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000050                  3816      2678 total