5 ms·

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

by spc476 2y ago

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!"

abetusk 2y ago
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?
- spc476 2y ago
  > 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.
khaki54 2y ago
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
burutthrow1234 2y ago
`strace -c` will show you wall time per call and not just the volume of syscalls.
o11c 2y ago
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)
- spc476 2y ago
  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.
- spc476 2y ago
  Turns out that mmap() is the memory allocator, nothing to do with files.
  - throwway120385 2y ago
    I was going to point out that you can mmap() anonymous pages and use them directly as heap so this tracks.
vidarh 2y ago
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.

by spc476 2y ago

abetusk 2y ago

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?

spc476 2y ago
> 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.

khaki54 2y ago

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

burutthrow1234 2y ago

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

o11c 2y ago

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)

spc476 2y ago
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.
spc476 2y ago
Turns out that mmap() is the memory allocator, nothing to do with files.
- throwway120385 2y ago
  I was going to point out that you can mmap() anonymous pages and use them directly as heap so this tracks.

vidarh 2y ago

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.