From 68348394274ee83f5286022d97cfe58b6761321b Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Fri, 7 Oct 2016 17:25:26 -0400 Subject: [PATCH] runtime, cmd/trace: annotate different mark worker types Currently mark workers are shown in the trace as regular goroutines labeled "runtime.gcBgMarkWorker". That's somewhat unhelpful to an end user because of the opaque label and particularly unhelpful to runtime developers because it doesn't distinguish the different types of mark workers. Fix this by introducing a variant of the GoStart event called GoStartLabel that lets the runtime indicate a label for a goroutine execution span and using this to label mark worker executions as "GC ()" in the trace viewer. Since this bumps the trace version to 1.8, we also add test data for 1.7 traces. Change-Id: Id7b9c0536508430c661ffb9e40e436f3901ca121 Reviewed-on: https://go-review.googlesource.com/30702 Run-TryBot: Austin Clements TryBot-Result: Gobot Gobot Reviewed-by: Dmitry Vyukov --- src/cmd/trace/trace.go | 8 +++-- src/internal/trace/goroutines.go | 2 +- src/internal/trace/order.go | 2 +- src/internal/trace/parser.go | 16 +++++++--- src/internal/trace/testdata/http_1_7_good | Bin 0 -> 1971 bytes src/internal/trace/testdata/stress_1_7_good | Bin 0 -> 396526 bytes .../trace/testdata/stress_start_stop_1_7_good | Bin 0 -> 2055 bytes src/runtime/mgc.go | 8 +++++ src/runtime/trace.go | 30 +++++++++++++++--- 9 files changed, 52 insertions(+), 14 deletions(-) create mode 100644 src/internal/trace/testdata/http_1_7_good create mode 100644 src/internal/trace/testdata/stress_1_7_good create mode 100644 src/internal/trace/testdata/stress_start_stop_1_7_good diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go index 7670d330e1..26548fa9de 100644 --- a/src/cmd/trace/trace.go +++ b/src/cmd/trace/trace.go @@ -371,11 +371,15 @@ func generateTrace(params *traceParams) (ViewerData, error) { case trace.EvGCSweepStart: ctx.emitSlice(ev, "SWEEP") case trace.EvGCSweepDone: - case trace.EvGoStart: + case trace.EvGoStart, trace.EvGoStartLabel: ctx.grunnable-- ctx.grunning++ ctx.emitGoroutineCounters(ev) - ctx.emitSlice(ev, gnames[ev.G]) + if ev.Type == trace.EvGoStartLabel { + ctx.emitSlice(ev, ev.SArgs[0]) + } else { + ctx.emitSlice(ev, gnames[ev.G]) + } case trace.EvGoCreate: ctx.gcount++ ctx.grunnable++ diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go index f8673e20bc..f02c7eb91b 100644 --- a/src/internal/trace/goroutines.go +++ b/src/internal/trace/goroutines.go @@ -48,7 +48,7 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc { g := &GDesc{ID: ev.Args[0], CreationTime: ev.Ts, gdesc: new(gdesc)} g.blockSchedTime = ev.Ts gs[g.ID] = g - case EvGoStart: + case EvGoStart, EvGoStartLabel: g := gs[ev.G] if g.PC == 0 { g.PC = ev.Stk[0].PC diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go index 8ca2da52aa..4b788147d1 100644 --- a/src/internal/trace/order.go +++ b/src/internal/trace/order.go @@ -150,7 +150,7 @@ func stateTransition(ev *Event) (g uint64, init, next gState) { g = ev.G init = gState{1, gRunnable} next = gState{2, gWaiting} - case EvGoStart: + case EvGoStart, EvGoStartLabel: g = ev.G init = gState{ev.Args[1], gRunnable} next = gState{ev.Args[1] + 1, gRunning} diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index fa62eccf72..3110d6341f 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -28,12 +28,13 @@ type Event struct { StkID uint64 // unique stack ID Stk []*Frame // stack trace (can be empty) Args [3]uint64 // event-type-specific arguments + SArgs []string // event-type-specific string args // linked event (can be nil), depends on event type: // for GCStart: the GCStop // for GCScanStart: the GCScanDone // for GCSweepStart: the GCSweepDone // for GoCreate: first GoStart of the created goroutine - // for GoStart: the associated GoEnd, GoBlock or other blocking event + // for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event // for GoSched/GoPreempt: the next GoStart // for GoBlock and other blocking events: the unblock event // for GoUnblock: the associated GoStart @@ -126,7 +127,7 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri return } switch ver { - case 1005, 1007: + case 1005, 1007, 1008: break default: err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver) @@ -363,9 +364,12 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even } } switch raw.typ { - case EvGoStart, EvGoStartLocal: + case EvGoStart, EvGoStartLocal, EvGoStartLabel: lastG = e.Args[0] e.G = lastG + if raw.typ == EvGoStartLabel { + e.SArgs = []string{strings[e.Args[2]]} + } case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone: e.G = 0 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, @@ -599,7 +603,7 @@ func postProcessTrace(ver int, events []*Event) error { return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) } gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev} - case EvGoStart: + case EvGoStart, EvGoStartLabel: if g.state != gRunnable { return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts) } @@ -890,7 +894,8 @@ const ( EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] - EvCount = 41 + EvGoStartLabel = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id] + EvCount = 42 ) var EventDescriptions = [EvCount]struct { @@ -940,4 +945,5 @@ var EventDescriptions = [EvCount]struct { EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}}, EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}}, EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}}, + EvGoStartLabel: {"GoStartLabel", 1008, false, []string{"g", "seq", "label"}}, } diff --git a/src/internal/trace/testdata/http_1_7_good b/src/internal/trace/testdata/http_1_7_good new file mode 100644 index 0000000000000000000000000000000000000000..b0e318e9a44aec862b9151664fee01e4d581a7c2 GIT binary patch literal 1971 zcma)6U1(cX9Pjzxk9;(_Nt&ijKelyUPn)#$UIW8bpX@_71Sh(d^<@z6lAAP|+#7Fh z*6C9MD+(Q*t4{Y|s>0^nEXBdpb-H$VCxR}FISYz7MAq#=P!SnZ{JQ5RH&{oAc{tph z^ZWhI@Bej@N>7B}(W9wiOlmTIqfIMw`sv%KOgA9}W#%2)N5PZhzA`-tG(>knnSP97 zAo?&>WJLW*d5|6TcOY|dJ32N#Yf5FE?f$UM_h$Mn0$uI z%}xHfaCxbMW!NFO@W-82jNG|rb1^ZU=BL$^CSlkiOeq;j5c4@LB@0P~ zk4p!HoEj6VIN`bKM>L(1^9Q41CjP*7KB-`;rZj0P(Ly67ODHd=4iW{%tK|65;LcQ9 z3Rms01NB6doRBbpQHyN*H@V`#-rImoE_HOMd09&tA)968$2C#a_(WcgMX-~vC$NE2 zWhNCp>}1xCe@-EI+rE73Gm4_mq2q7NPz?JUTK(n_WwXzr7tSB19L^rx?5k?zS@n1dD1IZt=i-r;5<*`W;?9 zwg7H!fyJIS3$Rfedp*{HW}L{9ihW*d$AaRP+E!?AcbM42{x(_CgegtSMhTpsFqYk7 zO2)1C)w605gp7f!u#Bh!4)T{L3vTPGVa#*ET+MSMu85mme`NtYMm%R1OW@_cr%#qk z;NxCrKUpq83wN9OVf_mDTm5%V6d=&{Bda@I=-SKG6tuUfm8Ph)!vq<491PWSTLstp z0C)H|ZkbJmJ2@*``=x}UO8Wi4UR|1p_TUPdfB!Jm;cUOWR)S9MB3m>~-n_>oOCe-D zJi5b<&VE1|sS|g(EU#u>x*PUTR#jp~59tnst}V_&SNBtRQ>_{INMhU!SNAo;nbmpN z6#NdpFt6&yn?2T5`;)n8Ny_3aLydBhNybd5c_V|~TzMWgZ+Q^+v|3W;*zHorV^dNb zZ><>_*OY7}@4Z$rY7?qt@iw=WOEIBIsy^bg9h-RxdV&kKm3QZ1Yw#Cz!f@T|3@@&i zU>kRx{qrMI_n-fpQrs7?oESBUNlC*;I%_C8X;eHn3w_;RA&hH*8`wljeg^l48wPIR z#54)p$)ckdW&roUi12_bkd6=|!9uFm;}w$rh}Y5RmHGR6 zks1iyMW3z}sc@(Wcg^5`x+nO-TE5B4l9S|k1P=wQ)KXFs4M!{FV6K?`-P@qQ@o=peIr0uqOi7c9nvUxuHruy<&BAc^QQPt&nV1{@ Hb7KAh7L2PN literal 0 HcmV?d00001 diff --git a/src/internal/trace/testdata/stress_1_7_good b/src/internal/trace/testdata/stress_1_7_good new file mode 100644 index 0000000000000000000000000000000000000000..b4d927de341aa47e95cd5e530660550832cfcaa7 GIT binary patch literal 396526 zcmZskcVL{w@%Qia+&x!xmR!|rOY(DS?hV^C0|AyMnvCdG6orrkLTG_NXf_xOqJ-WI z#2`utgwP=*gih#SoIpq*KnNkE0RckE`}xj3&*_}s>p$e@nP+x(c6N4lc6N5}>xZ?^ zowca_$nOpua8QbWUrP-?x#re)(=HW+Gu;=tFdXaNDTYHwjZODonjRhAmM*+_$?|k@ z&UDP+GAzYevmjY^czW`K<`f3}( zeck)%OgPD11Ee|XD>Z~$yQhJSb3X%88}*H92=_3YaqdSz3I;jIt$@yWw-QLbL3VeK zWHaG5ZcWZA8{H6|mv$EinXtj#9t4ApuH0~zbCtCTv}T?}NL`wtAYMSb8bPrC;JHM#RV zA=bGVKB*lHJL5829H1f2$V8k9Yq?ddz!^Ti`&ThYIQoaA|?)b>1!!x4VAi(9I;d--fdy(*>NfkXOhRoY!fv8JR` zY1k4It7nlx2kEWcRo0AHUBKDFePx8i^ypX|VtTCm3lJ~*En+%?I-BWce)8E z9z52mQlPO_lzU?(`zv%15Or-Gci107Q=mUAXb7)QyERyW4c(pCh4E2egG|n9XqVkv zw8Pu3J>7Fa+TDvDGPWVy-(3%+(Vd(zWf<2G9^!rqoo4qkIJ6Zju$Q|ZoC)q$UkaQ9 z-70Wqx_99SoO;=pXRYo2@9v%eGQr*8agay9`*KVs>~N0(p`}>KTJbaxYNuVhx?j+W1@2eAUGTG)y9b=fwAc6nvbVb($aw6jQKr;x?p`2GU?%d} z#k~t;lKU+XPkGS&97v<#c*ySVXI4sdyu|i*KQWjO9 z_#Paz`KZx2q!jbfZtgy#{Id$>J>5@?^3Od4I{O*rCijG=OuP1v`}9ta1Dyfp4@vc2 z522-d#Iwjl6`Z}?+s4noDmZ(`IKQmm>~8!tBDX|7`?x!dpO_9hzLQC;l|C}F2|xQ; zyC%5DeJLRO#Pazy5ZVr8z&&IfO7e_UAm6m!nU?4(key@6kI>mSmi(ih4(;00cy0!s z^yyx)4AndI7kzOMG^MK#dK~1_Z>1(!U-oS&1`|sq^{kKp9$7d zBnHmzHtjYb$)t9#8xxR!FgVU|_J}2R9}us-d(bbLaH8ROo_8|IHz#@shcbc#*S~re)NKRSvG-E zSigPU8iNRDjFsBQq}uEr0peS+t9#Vi^$TALX?QEzNLv!h`(l}8H~#5ytanuV1k*a| z0`i@>2W7ROOe=P^wl`I2<{s{^l$xCAn912|rnHwm?96>VUY8H9EX7>7+ZJ9z!sH@1+m#3;3|=|+otz}IEAPS&Q$ zG|IPhANQI;;<})`n@M$ojRIeLzxx=R7PF8*@O{08H({58!MDq^z{NN4mZ(^OC3^}@IUw5Ti0QjJL|+O>mCgiXM$T|oA7pXD{wO!kU&p=IJ;e+?$JK9dgfxc0@tDTV%JRC7bxtq*2> zHlG@70rUBE5zN12CbgbX1LocN!eCRe|1aqjuFFK#{YqN8*w08VU^|}91VeSvZ_?_< zo!mz?VK~*DVf?(B_BL+~u$jhVDf*r9y^}jH2vLbs!K;scZ+!3W-URk7_j#rmUYK@E zM+HNL=#8`t&ep6!3gHja?!9qgctslb3x12)@u|Uj`2AD57Jiq(@3ZMJ=N<}*gUz-5 z&%tkt8xm$d+mIS8WtVpV`*ohtlQL;D+V?d)G+~-=pVQ<^G%VsiAYy+2(<_ zipxKLu4c(w%WK*O*VJT}?B5=~kuIE@E51{5pN}qttJCiNFc@l&uCD28mos)nO@62; z2zzHor3>h(^58~6@7SocX&G~=?e`?v8{!$Am|+xm6ls|>%|yQTWBOU5;YIqJ|^50m9`KGsEvtA zn+VEd6qR=ED;mQP{-&>^e?e#X)3p2jwdwru0%UVTO}YQep49LQ64ab>|I>A;;VC?p z%l&tiQp2YR++1Fry>v=;QmXK+;!k!S_(}THr;Gd7o^;YlHNzVRsr;;^vx`&uugj$d zr&^`U8u~_;2VYJHz3oxy7Br$fcpfhkqteZ&LV55kUK*p)xoMaSFHgIzgQ1DhBQ^3Y zU#)ScXY%TVOP19XhG$dx=`i@l7OC**bm6>d#g8Vq|CEa1)iv%00tw~ly_&vqLwIY* zoLfYJwHm-q;-4SmhJ#|*?N;KkV{d^R>rTlOhvo+}dS^wYdr|1};D9l*J0fScniUL< zjXtQ+#CcNMtqzJqQ7~J$51{Df!4rbswy3nf8qgc`HbEBfaB-Uix8AiFq@F z?jQ}=%Anip5hw`T3t@9poF#hPIOrW6m39#VP;|(Ofs4HMh@o_EpY6uT=_Xhc)aPrI9g z{NQBMrNe0q2Jl)4(aEUGS!s6@U%P_do~ZP&hD&%x+WpRVIsM4X6?|{A(g&&Z_U=;8 z2D8bjX?KDDI@xzDM(=7*o3fbLSNK{smA)aZ!aKQ3Dx^;%QsoPy6*o$>I1fMLb3@eE zY{8v1{_~=!bcty?!n&4)U}MxbyCJ+U?fz}l`&&EF)vqYn6!lF;mDBFOh^v)_qS2z2 zm(a>=K8z%Ktv*{C!mHBmQ?RDE9|Q8TU?4pNXp;L2AOdA{&jo2W#As@_K``AUc6Hjl zW8_}}i;1qaA-o7{3|5Ta6C^*?Y4Tv@}pfKaB0ZoTt zE7;Kxo||?j8LdYE!33AMfJ6j8ft6 zYupHKea$QZB2j7#q#e1A!QMuExC-q=x1M zyUQ}6WSAyg1&2#HOqTJ2A^W}t#W`vB zQ(TA%(W8Mz?04N|v~X7N_1<-&(mi5q@LI6TQR(!w2LJ78MO5JOi9m+gtvB~esn)2%GCHrMNQiUUnf3F+()MmDVX13Ltjf2Bd`7M`j#N2it zb6Zc)J1;8Tnduu>9=sTqG0#_6)0gvt{k_zhuDK1nd{gBM0`=1Uf%W5vaOovJ(0;rm zb=le0f3Y0TG-CK!>Ja(>3n?^&dZB$$?@(rieL0C2?E6_2+0$>3#_+2nDrhGf7CuZ& zj1M$`?)ttFh8E9ijCCC|-l0}IUI>(qw8G#s=czt$U>HhFi>T)bnoo|h*$I1&9v)*d zp&6j?%ydcr@_ekB;y3MCjhGXa?y?Gw4f@yb3}3HtZz;I{T8$gpA{g2<`dc6`OeU%} zHT;hnhFf>Je<{x2uhNB^#}!u=+^KcewdbP~QS{G1<_n#80iD<=I5({s1}~F7BQU1P zlWu~I(|JL%7pu)u(bpIma$k-m| z9t3~O;Ocbm`cdh(#_|Q=GgRp&W+F`Qd~xuVjgn<)cU`71)E@lESRS^XJkI=;>#XdS zR@GtZ7#H-n*hK#Yk-y=&2=wPcx&P6vQsJ6(;kT{DN1NQgN(C)WuEPy(iLT4YSTftK z$Q7`~Yv6KpG@Q}$kZNzuhC|bWThkiAwA`lW->#!_H)i@+XkC+bS7QaIVlZqzSf?TU zaoW9@Enrdq<}E67-q~sQ1y~Wr-6oO+4O+GQ4N#lA91s&pTSNGhv|9A>B?Xxen5W?WLu#C4(;$-)odsWC0cyjtS&bMRCh<1_O<@X1rmp8kyI(-7 z-JJu7Sr#m&)YAb?u^JZ{t2g1W0P3Xw4U1heL@4gt*sHQO!aZ$VWlU&c?kAI6eg+lm1jr$B}6#d%jMRv~t-Q2wmaBTF9DcfynJRSM&BXjPV z>aQYlxy8!`mAps&RYYli42Uj7kA9YBoE7Pumk||mVVa{?PX^>Ce(#X50rD>7rgXMie{I@T_nnd54W-;bi9^VTV zo*4yc53c0RX>_WHE+a!}sV6U1C%aEj5Nf1}$6I^GxTU51a5p;fu%^BnzLTAiDjZY1 zanit-Ba6D#*>!_Iq*M8Im#)X$_Z)K{YgbkZZ)f_(mItrH4l(Vo43g;r-vjp;JBl<` zPFJ)5MB-%5{g*Xa*>*_0AXrxY%9d%0->^79EskKjL@j&@2(cohbs~`)L9}rI4r_qJ z2~w%a&jBIAgcOb?22)iEItN3c$f$qC<3Q&JL~bO4mpmOH#}PVHXKC{VIzWzzal{X` zL+5)0#?=XNU>wM?1VU6wI7F&|98I`SI12bf2gq?T&*IS2In?TEvv&EG9!Gpj9E!5X zInp4LEwBj={2XD+*h$33MsV)7x)en9wI6A1Z>^Hpk%R|DSz&q4&k+V`chCD$Q2ri) zYvG6vwIjpt5%H3IMkIfXwaatpm&`{I(p0I3eJT96BaF@@wmggul)p=$SUBo0#vG7i z33ZCHS_;oVmZPTzrHw036=P1NoDO@pBs(P>$Yc|7~uGa)O^QyC)*%xA~0 zUIeI0;T4Ax8||0lzeaR-Fq!91N}HJ%4~KMy@1 zYY}3x-UrK1b9h8w0cw+*ArRJ&sp)TkX1PC55D>I5GrtDZZnKqN(9ocd0ZnqlU{&U! z>#aeWttf~Hv31Lgi5Dx}KQ_ueU|3gzMYEZQXyZwM+TDM^Vlt#4J^du)du&Dq3lR=! znH`3s+|O&n;VwG=dFG}Ew@8JXV26XDEut%}*T}|DmA?tJc{9`n|=+;61#Ln>XwEOFC2qbkN?5pYSPo}1ZBc6N8{cFah!qYaDUaxFuN!?gRtj%OBZ0E&SrX?WDD4HYq5}n2iwyUxlWZonmibAk51n$?-XZzwOR~A~+qS9lA#VU$_%|=N$)Dc_|^iE}FHkbc+>mJtQ=++UoM!QyF%j^Tp?Z%^E?7A| zl%+qOnJ^^CdUep-WhBsYmWU_~>q1Bm(LR*vMA{vGR%20x`smD1I}V4lD;b7=O1m## zLUSh5A7|1Zw{)b2KT?OzE%#qZZ2Cn#x6?VFP0g;KD(q2QId