Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
robaho opened this issue Nov 29, 2018 · 8 comments
Open

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

robaho opened this issue Nov 29, 2018 · 8 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@robaho
Copy link

robaho commented Nov 29, 2018

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:

image

and here is when I scroll down to the running:

image

@agnivade agnivade changed the title trace does not track or report in-syscall properly cmd/trace: does not track or report in-syscall properly Nov 29, 2018
@agnivade agnivade added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 29, 2018
@randall77
Copy link
Contributor

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
Copy link
Author

robaho commented Nov 29, 2018

@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
Copy link
Contributor

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
Copy link
Author

robaho commented Nov 29, 2018

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
Copy link
Contributor

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
Copy link
Author

robaho commented Nov 29, 2018

@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
Copy link
Contributor

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

CC @hyangah

@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Nov 29, 2018
@robaho
Copy link
Author

robaho commented Dec 1, 2018

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.

image

image

@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jul 7, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

5 participants