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.

[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 

Re: [go-nuts] Trace explicit goroutine function names replaced by synthetic ones 1.18beta1

[Rich Moyse]

Ian:

Appreciate your guidance.  

Created issue #50622 <https://github.com/golang/go/issues/50622>.

Rich
On Friday, January 14, 2022 at 1:12:38 PM UTC-5 Ian Lance Taylor wrote:

> On Fri, Jan 14, 2022 at 10:03 AM Rich Moyse  wrote:
> >
> > When viewing a trace produced by 1.18beta1, the goroutine function names 
> reflect synthetically generated ones typically assigned to 
> anonymous/closure functions.
> >
> > For example, a function explicitly named: "msgSend" in the "main" 
> package appears on the trace "/goroutines" page as: "main.main.func1" 
> instead of "main.msgSend". This issue also occurs when viewing specific 
> goroutine events selected from the trace timeline. In this situation, the 
> event "Title" field again reflects "main.main.func1" instead of 
> "main.msgSend".
> >
> > I noticed this issue when comparing the output of a trace produced by 
> the 1.17 "go tool trace" versus the one generated by 1.18beta1.
> >
> > Has anyone else notice this issue? Am I missing some configuration 
> setting that would configure the "go tool trace" to display explicit names 
> instead of synthetic ones?
> >
> > The following github links provide the mentioned:
> >
> > go source,
> > 1.17 trace file,
> > 1.18beta1 trace file.
>
> That doesn't seem like an intended change. Please open an issue for
> this at http://go.dev/issue. Thanks.
>
> Ian
>

-- 
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/7da8cd8a-8b43-4b60-b55b-beccbb504dd6n%40googlegroups.com.

[go-nuts] Trace explicit goroutine function names replaced by synthetic ones 1.18beta1

[Rich Moyse]

When viewing a trace produced by 1.18beta1,  the goroutine function names 
reflect synthetically generated ones typically assigned to 
anonymous/closure functions.

For example, a function explicitly named:  "*msgSend*" in the "main" 
package appears on the trace "/goroutines" page as: "*main.main.func1*" 
instead of "*main.**msgSend"*.  This issue also occurs when viewing 
specific goroutine events selected from the trace timeline.  In this 
situation, the event "Title" field again reflects "*main.main.func1*" 
instead of "*main.msgSend*".

I noticed this issue when comparing the output of a trace produced  by the 
1.17 "go tool trace" versus the one generated by 1.18beta1.

Has anyone else notice this issue?  Am I missing some configuration setting 
that would configure the "go tool trace" to display explicit names instead 
of synthetic ones?

The following github links provide the mentioned:

   -  go source 
   

   ,
   - 1.17 trace file 
   

   ,
   - 1.18beta1 trace file 
   

   .
   

-- 
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/85b946dc-6afe-4b38-a2a8-4e9a02ff0e5bn%40googlegroups.com.

[go-nuts] generics go2go Type List in Interface - Struct Type

[Rich Moyse]

Attempting to use a Type List in an Interface 

 
to restrict the types allowed to instantiate a generic function (example in 
go2go ).  The Type List within 
the Constraint Interface (Santa) contains only one struct type 
 (SantaSad).  This struct type 
and a second, independent struct type (SantaHappy) both implement the 
Constraint Interface (Santa) specified as a type parameter for the generic 
function.  Given this situation, I expected the instantiation of the 
generic function with a type argument of the type (SantaSad), that appears 
in the Constraint's Interface Type List to succeed, which it does, and 
instantiating the generic function with the struct type, absent from the 
Type List (SantaHappy), to fail.  However, instead of failing, this second 
case succeeds.  Is this the intended behavior?


-- 
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/44b6cb78-d143-437f-b4e0-f1cf8d642989n%40googlegroups.com.