Hacker News Reader

Comment by vidarh | Hacker News Reader

"strace -c" is usually how I start looking for things like this. It so often immediately reveal some vast difference in syscalls that'll give a clue, and is usually faster/more convenient as a first step than starting with a full profiler trace or looking through code.

View on HN

strace was not on my radar. I know it exists, it just never occurred to me to use it. So, I tried it. Here are the results:

    4542 open
    3041 read
    2990 close
    2517 epoll_ctl
    2478 old_mmap
    2475 munmap
    2470 fstat64
    1509 epoll_wait
    1509 clock_gettime
    1501 ioctl

ioctl() (that, combined with epoll_ctl() and epoll_wait(), which was the actual problem) does show up in the top 10, but it doesn't scream "I'm the issue!"

My apologies, I'm just unfamiliar with what would look normal. These are the results of the buggy TCP implementation? Could you show a comparison for the fixed TCP implementation and the TLS implementation?

> These are the results of the buggy TCP implementation?

Yes. Here's the fixed TCP implementation.

    4542 open
    3041 read
    2990 close
    2478 old_mmap
    2475 munmap
    2470 fstat64
    1501 epoll_ctl
    1007 fcntl64
    1002 epoll_wait
    1002 clock_gettime

I didn't do the TLS implementation, but I suspect it would be similar to the above (since it didn't exhibit the problem). You can see that ioctl() dropped from the list, and that epoll_ctl() and epoll_wait() dropped down the list.

Not for me either in this case, but often times you will see it's running down some error branch repeatedly, and will sometimes give you a filename of what it's working on, which can be a big clue

`strace -c` will show you wall time per call and not just the volume of syscalls.

It should kind of jump out for not being an "actually do something useful" syscall.

Without knowing what your program does, what your syscalls say to me are:

* why are so many files opened but not closed?

* that's probably too much epoll_ctl; try optimistically performing the real syscall once before actually registering. Or, under some circumstances, do a quick few-fd `poll` since it is stateless.

* is mmap really a win here? Unless you need its swap-like behavior, read is often faster (and it avoids ToCToU). Also, why are there fewer `fstat`s than `munmap`s?

* why is there an ioctl so prominent; what is it even doing?

* that's a lot of reading but no writing ... I guess maybe it's split across multiple lower syscalls but it's still weird.

(of course, all these can have legitimate answers, but you need to know them)

I do know how to answer most of the questions.

The program is a gopher server. The list you see is the result of sending several hundred (sequential) requests to the server. The number of calls to open() vs. close() can be explained [1], so (to me) nothing unusual there. I don't directly call mmap(), munmap() or fstat(), so I'm assuming there's some code in some library I'm using that's doing those calls. And that's the assumption I would have with ioctl() as well (well, I now know better, but in investigating the issue originally I might just ignored ioctl() along with mmap()).

There is a lot of reading, due to the requests (blog entries). Writing is to a socket.

You are right in that there is too much epoll_ctl(), but it's unclear to me if I would have found the actual issue. I did do change the code to perform the real system call before registering, but that had little effect.

[1] Not all requests are valid, for instance. In this case, it's a mirror of my blog, and due to how I use the file system as a DB, there may or may not be files of meta data that exist.

Turns out that mmap() is the memory allocator, nothing to do with files.

I was going to point out that you can mmap() anonymous pages and use them directly as heap so this tracks.

I did suspect that, but now the implication is that the memory allocator is not reusing memory even though it easily could.

GLIBC used to have a fixed 128 KiB threshold, but since 2.25 (2017) it defaults to dynamically adjusting the threshold to prevent exactly this pattern of excess syscalls. A manual threshold disables this though!

(This may be a microoptimization depending on how much real work you're doing between the syscalls, but there's also a good chance that it's easy to fix.)

> * why are so many files opened but not closed?

Guess: about 1/3 of those opens are unsuccessful.

You'll need to get used to comparing it to more "usual" output, I guess. Ioctl() is a syscall you'd very rarely expect to see many of in most code. If I'm seeing more than half a dozen ioctl's, I'll be wondering what is going on (doesn't mean it has to be something wrong, just unusual).

But also, you'll want to look at the wall time and the microseconds per call - the raw syscall count is much less interesting.

Once you then spot something odd, dropping the "-c" and using "--trace=" to set which syscalls you're interested in tracing, and getting a live dump of the syscalls while you're testing often reveals very "interesting" patterns (favourite pet peeve: Looking for small reads/writes - context switch overhead almost always makes it pay to buffer in userspace, but a surprising number of applications fail to do so)

Basically, my assumption w/networking code is that if I'm stress-testing it and the wall-time isn't dominated by read/write, something is very wrong.

You can often get pretty far with `perf top`, also. Maybe not so much in this case, where it sounds like the overall CPU used was low compared to the amount available from the system, but for hot-spots it can be handy.

yup, plus if the program is already running in the bad state you don't even have to restart it to investigate, just do

  strace -p <pid> -c

to attach

Reply on news.ycombinator.com