Re: [go-nuts] cmd/trace: Indirect reporting of OS Latency?

[Robert Engels]

A windows machine won’t have ‘perf sched’. 

I don’t think Windows has similar lowlevel scheduling tracing - at least not 
that I remember. 

I suggest installing Linux on a separate partition and direct booting. 

Linux has a LOT of scheduling tracing/tuning options - some require a custom 
kernel. 

Have fun!


> On Feb 12, 2022, at 8:51 PM, Rich Moyse  wrote:
> 
> 
> Robert, thanks for your reply - especially the link to perf sched!  I plan to 
> run the go program on Windows physical machine.  I'll post my results once 
> done.
> 
> -- 
> You received this message because you are subscribed to the Google Groups 
> "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an 
> email to golang-nuts+unsubscr...@googlegroups.com.
> To view this discussion on the web visit 
> https://groups.google.com/d/msgid/golang-nuts/18ebe8c8-4741-4e0f-93a1-0c316444588an%40googlegroups.com.

-- 
You received this message because you are subscribed to the Google Groups 
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to golang-nuts+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/golang-nuts/F1F3C1AC-37B8-4D98-8BC2-7165C1E7F9C0%40ix.netcom.com.

Re: [go-nuts] cmd/trace: Indirect reporting of OS Latency?

[Rich Moyse]

Robert, thanks for your reply - especially the link to *perf sched*!  I 
plan to run the go program on Windows physical machine.  I'll post my 
results once done.

-- 
You received this message because you are subscribed to the Google Groups 
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to golang-nuts+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/golang-nuts/18ebe8c8-4741-4e0f-93a1-0c316444588an%40googlegroups.com.

Re: [go-nuts] cmd/trace: Indirect reporting of OS Latency?

[robert engels]

I suggest you use the linux scheduler tracing facilities, e.g. perf shed to 
diagnose (see https://www.brendangregg.com/perf.html#SchedulerAnalysis 
)

But you may have to also do this outside the VM - to schedule trace the VM.

In general, timing at 1ms intervals with a 2% error is probably all you can 
expect running in a VM - especially if you don’t know (or manage) the load on 
the bare metal. 2% on 1ms is 20 us - and a raw bare metal scheduler will 
probably only get you to 5-6 us.

You can simplify your analysis by testing on bare metal first.



> On Feb 11, 2022, at 10:05 PM, Rich Moyse  wrote:
> 
> TLDR
> I’d be grateful if someone could either confirm or dismiss the effect of OS, 
> go runtime, and/or Hypervisor latency on the output of a goroutine trace.  
> The trace report displays empty gaps of 3-14ms where expected periodic 
> goroutines should execute, as there’s a goroutine triggered by each 1ms timer 
> tick.  Attempts to select items within these gaps return only five “counter” 
> items - nothing else.  Those counter items suggest that nothing is running.  
> Perhaps external preemptive behavior interrupts the running go process, 
> thereby suspending the go runtime, causing these gaps?  If so, can these 
> trace gaps be attributed to OS and/or Hypervisor scheduler preemption?
> 
> 
> Although a recent (2/4/2022) go-nuts summary mentions a post to the thread: 
> Issues when using time.Ticker microsecond duration 
> , whose 
> other posts discuss a range of causes, including OS induced latency, this 
> thread attempts to understand how external latency sources affect the trace 
> report.
> 
> In addition to the problem description below, the go code and trace screen 
> images are available via this gist 
>  
> while the trace file is available here 
> .
>   The go program was compiled first using 1.18beta1 and later with 1.17.  
> It’s running in a 16.04 Ubuntu Desktop VM that’s managed by Hyper-V on a 
> physical machine running Windows 10 Pro.  The go program limits itself to the 
> interplay between two goroutines: a single sending goroutine and a single 
> receiving one.
> 
> These goroutines share an unbuffered channel.  The sender is only throttled 
> by the capacity of the receiver to consume its messages while the receiver is 
> gated by a timer that ticks in 1ms 
>  intervals.  The sending code 
> executes in ~600ns  then blocks 
> waiting for the receiver.  The receiver executes in ~8us 
> , starting after the ticker 
> expires until it's blocked waiting for the timer’s next tick.  Due to their 
> speedy execution, the go runtime scheduler never intervenes to preemptively 
> interrupt either goroutine.  Moreover, the garbage collector doesn’t run 
> because only this same pair of goroutines are active and the message 
> communicated between them is an empty structure.
> 
> In general the regular rhythm of the receiver’s timer appears in the 
> “Goroutine analysis” view of the trace report as evenly spaced markings at 
> nearly one 1ms intervals.  However, these ruler-like markings are 
> sporadically absent resulting in gaps between 3-14ms.  During these gaps 
> neither the receiving goroutine nor its coupled sender execute.  When 
> selecting the rectangular gap area only “5 items'' are reported as selected. 
> These 5 items displayed by the “Counter Samples (5)” tab indicate that no 
> goroutines are “Running”, nor are there “Runnable” ones.  Here are all the 
> counters reported by the selected gap appearing at time: ~502ms into the 
> trace report: 
>   
> Counter  Series Time   
> Value
> 
> Goroutines GCWaiting 502.3296180004 0
> 
> GoroutinesRunnable  502.32961800040
> 
> GoroutinesRunning   502.32961800040
> 
> Threads   InSyscall 501.2523010
> 
>  Threads  Running   501.2523011
> 
> 
> Since the program was running trace, to collect the data needed to produce 
> its report, perhaps the trace itself induced a measure of go runtime latency? 
>  To eliminate this potential latency source, the trace package and its 
> associated http server goroutine were eliminated.  Instead, latency events 
> were directly detected and reported by the receiving goroutine.  This 
> goroutine computed the latency between timer ticks by remembering the prior 
> timer value and subtracting it from the newly provided one.  It outputted, 
> via fmt.Print, a message whenever the computed latency exceeded 5ms. 

[go-nuts] cmd/trace: Indirect reporting of OS Latency?

[Rich Moyse]

*TLDR*

I’d be grateful if someone could either confirm or dismiss the effect of 
OS, go runtime, and/or Hypervisor latency on the output of a goroutine 
trace.  The trace report displays empty gaps of 3-14ms where expected 
periodic goroutines should execute, as there’s a goroutine triggered by 
each 1ms timer tick.  Attempts to select items within these gaps return only 
five “counter” items - nothing else.  Those counter items suggest that 
nothing is running.  Perhaps external preemptive behavior interrupts the 
running go process, thereby suspending the go runtime, causing these gaps?  
If so, can these trace gaps be attributed to OS and/or Hypervisor scheduler 
preemption?

Although a recent (2/4/2022) go-nuts summary mentions a post to the thread: 
Issues 
when using time.Ticker microsecond duration 
, 
whose other posts discuss a range of causes, including OS induced latency, 
this thread attempts to understand how external latency sources affect the 
trace report.

In addition to the problem description below, the go code and trace screen 
images are available via this gist 
 
while the trace file is available here 
.
  
The go program was compiled first using 1.18beta1 and later with 1.17.  
It’s running in a 16.04 Ubuntu Desktop VM that’s managed by Hyper-V on a 
physical machine running Windows 10 Pro.  The go program limits itself to 
the interplay between two goroutines: a single sending goroutine and a 
single receiving one.

These goroutines share an unbuffered channel.  The sender is only throttled 
by the capacity of the receiver to consume its messages while the receiver 
is gated by a timer that ticks in 1ms 
 intervals.  The sending code 
executes in ~600ns  then blocks 
waiting for the receiver.  The receiver executes in ~8us 
, starting after the ticker 
expires until it's blocked waiting for the timer’s next tick.  Due to their 
speedy execution, the go runtime scheduler never intervenes to preemptively 
interrupt either goroutine.  Moreover, the garbage collector doesn’t run 
because only this same pair of goroutines are active and the message 
communicated between them is an empty structure.

In general the regular rhythm of the receiver’s timer appears in the 
“Goroutine analysis” view of the trace report as evenly spaced markings at 
nearly one 1ms intervals.  However, these ruler-like markings are 
sporadically absent resulting in gaps between 3-14ms.  During these gaps 
neither the receiving goroutine nor its coupled sender execute.  When 
selecting the rectangular gap area only “5 items'' are reported as 
selected. These 5 items displayed by the “Counter Samples (5)” tab indicate 
that no goroutines are “Running”, nor are there “Runnable” ones.  Here are 
all the counters reported by the selected gap appearing at time: ~502ms 
into the trace report:  *Counter*  *Series  *   *Time  
 Value*

Goroutines GCWaiting 502.3296180004 0

Goroutines Runnable 502.3296180004 0

Goroutines Running 502.3296180004 0

Threads InSyscall 501.252301 0

Threads Running 501.252301 1

Since the program was running trace, to collect the data needed to produce 
its report, perhaps the trace itself induced a measure of go runtime 
latency?  To eliminate this potential latency source, the trace package and 
its associated http server goroutine were eliminated.  Instead, latency 
events were directly detected and reported by the receiving goroutine.  
This goroutine computed the latency between timer ticks by remembering the 
prior timer value and subtracting it from the newly provided one.  It 
outputted, via fmt.Print, a message whenever the computed latency exceeded 
5ms.  It’s source, main_latencycompute.go 

 
is provided by the same gist 
.

Before running the newly altered program, I half thought removing the 
overhead of collecting trace data would eliminate the latency gaps depicted 
in its reporting.  However, after a bit of waiting, the altered program 
began issuing sporadic latency messages.  Furthermore, the activities of 
opening a new terminal window or moving existing windows with a mouse, 
caused the altered program to seemingly generate latency messages with 
greater frequency.  On noticing this behavior it seemed likely to me that 
the empty gaps depicted by the trace report represent latency introduced by 
the OS scheduler, as it preemptively stops and then restarts the go program.

After