The mighty strace has let me down. How is this possible?

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, I can see how it is waiting in strace - i.e. what system call is blocking for a long period of time. Unfortunately this approach didn't work.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls. But this particular process showed as spending negligible overall (real) time inside system calls.

foo is actually journalctl -b -u dev-hugepages.mount. Except that the last argument must be changed to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happens the first time that I try to get the logs for any one systemd unit. It is an issue which does not occur on all systems. https://github.com/systemd/systemd/issues/7963

The mighty strace has let me down. How is this possible?

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, I can see how it is waiting in strace - i.e. what system call is blocking for a long period of time. Unfortunately this approach didn't work.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls. But this particular process showed as spending negligible overall (real) time inside system calls.

foo is actually journalctl -b -u dev-hugepages.mount. Except that I had to change the last argument to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happened the first time that I try to get the logs for any one systemd unit. EDIT: after answering the main question, I also realized the reason I was having this problem reproducing the delay.

The time spent by this process is a specific issue, apparently it does not occur on all systems. https://github.com/systemd/systemd/issues/7963

All hail strace.

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, strace will show how it is waiting, i.e. what system call is blocking for a long period of time. Unfortunately this approach didn't work.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls. But this particular process showed as spending negligible overall (real) time inside system calls.

How is it possible that strace lets me down in this case?

foo is actually journalctl -b -u dev-hugepages.mount. Except that the last argument must be changed to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happens the first time that I try to get the logs for any one systemd unit. It is an issue which does not occur on all systems. https://github.com/systemd/systemd/issues/7963

The mighty strace has let me down. How is this possible?

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, I can see how it is waiting in strace - i.e. what system call is blocking for a long period of time. Unfortunately this approach didn't work.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls. But this particular process showed as spending negligible overall (real) time inside system calls.

foo is actually journalctl -b -u dev-hugepages.mount. Except that the last argument must be changed to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happens the first time that I try to get the logs for any one systemd unit. It is an issue which does not occur on all systems. https://github.com/systemd/systemd/issues/7963

All hail strace.

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, strace will show how it is waiting, i.e. what system call is blocking for a long period of time.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls.

But, this specific process also spends negligible overall (real) time inside system calls.

How is it possible that strace lets me down in this case?

foo is actually journalctl -b -u dev-hugepages.mount. Except that the last argument must be changed to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happens the first time that I try to get the logs for any one systemd unit. It is an issue which does not occur on all systems. https://github.com/systemd/systemd/issues/7963

All hail strace.

time foo shows that foo takes several seconds to run ("real"), but uses negligible cpu time, both in userspace ("user") and in the kernel ("sys"). For the curious, foo is defined below.

So it spends most of its time waiting for something else, not executing CPU instructions. Normally, strace will show how it is waiting, i.e. what system call is blocking for a long period of time. Unfortunately this approach didn't work.

strace -ttt -T -C -w foo shows system calls, timestamped, and a summary of the (real) time spent in system calls. But this particular process showed as spending negligible overall (real) time inside system calls.

How is it possible that strace lets me down in this case?

foo is actually journalctl -b -u dev-hugepages.mount. Except that the last argument must be changed to a different systemd unit each time in order to reproduce this. In other words, the delay I am investigating happens the first time that I try to get the logs for any one systemd unit. It is an issue which does not occur on all systems. https://github.com/systemd/systemd/issues/7963