cmd/trace: does not track or report in-syscall properly

[robaho]

What version of Go are you using (go version)?

1.11.2

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

osx, darwin, amd64

What did you do?

simple ping/pong network test here

you need to change the benchmark time to make it run longer

I selected an area of threads in the graph.

What did you expect to see?

Since it is a ping-pong, I would expect to see threads alternating between in-syscall, and running.

What did you see instead?

all of the in-syscall counts are 0, but the running alternates from 0 to 1 as expected

Here is a screen shot:

and here is when I scroll down to the running:

[randall77]

The runtime uses an event-based poller (kqueue on Darwin, I believe) so goroutines waiting for I/O are not actually waiting in a syscall.
Somewhere there's a runtime OS thread waiting inside runtime.netpoll. That thread might not be in the trace, I'm not sure how the network poller thread is reported.

[robaho]

@randall77 but when writing, wouldn't that thread (GoR) be in a syscall, and also, even if there is a poller thread, when there is data available, doesn't it schedule the GoR to perform the read (so then it should be in a syscall as well - doing the read) ?

edit: it doesn't say, 'waiting in syscall', it is labelled 'in-syscall' which I am assuming the thread marks before entering a syscall, and clears upon return - so some threads must be in a syscall at some point ?

[randall77]

When a goroutine calls into a "blocking" I/O operation, the I/O request is sent to the kernel and then the goroutine is suspended and put on a queue in the runtime. It does not occupy any OS thread stack at that point. The OS thread is now free to run another goroutine.
When the poller OS thread notices that the I/O has completed, it marks the goroutine associated with that I/O runnable and it becomes eligible for an OS thread to pick it up and start running it again.

The goroutine doesn't do the I/O directly (by "do", I mean issue a blocking syscall). It is suspended at the point of the I/O, but it is not in a syscall. (I think the goroutine does do a syscall, but just to initiate the I/O. That syscall isn't blocking.)

[robaho]

I get that, but even if it is not blocking I think that at some point it would show as in syscall. This category is threads not go routines.

[ianlancetaylor]

The sysmon thread will periodically check the runtime poller using a non-blocking call. The only time you should expect to see a thread stuck in the runtime poller system call is when the program has absolutely nothing else to do.

[robaho]

@ianlancetaylor I'm sorry but I don't follow. The trace view doesn't state "waiting in syscall", just "in syscall", so when the poller detects some data available for a waiting Go routine, doesn't it schedule that Go routine onto a thread to perform the read?

So I would expect these threads to be "in a syscall" - even if it is very short - a lot. So unless the trace works by stack sampling - which I didn't think so - it should be creating an event "in-syscall" just before the call, and then 'syscall complete' when the call returns.

Like I said, the "in syscall" values are 0 - always - so if it's not a bug, when would I expect to see a value there ?

[ianlancetaylor]

Oh, I see. I don't know what that number means.

CC @hyangah

[robaho]

Here's some additional info. Same code. Same workload. Different results. Notice that the threads have a little green in their graph. The network looks the same. But now the threads are 'in syscall'. So anyway, it looks to be working - so probably intermittent or I did something wrong. I'll keep an eye on it.