Fix #2909: Port per-phase profiling from scalac

[nicolasstucki]

Ported from scala/scala#5848

[nicolasstucki]

Here is the output of compiling the collection strawman

header	id	phaseId	phaseName	type	id	comment	wallClockTimeMs	idleTimeMs	cpuTimeMs	userTimeMs	allocatedMB	retainedHeapMB	gcTimeMs
GC	1898	1905
GC	3219	3231
GC	4380	4391
GC	4391	4553
data	1	1	frontend	single	-1	--	4587.644765	0.0	4351.438	4309.638	297.256608	103.026888	192
data	1	1	frontend	total	-1	--	4587.644765	0.0	4351.438	4309.638	297.256608	103.026888	192
data	1	2	sbt-deps	single	-1	--	0.658633	0.0	0.658	0.64	0.04648	0.0	0
data	1	2	sbt-deps	total	-1	--	0.658633	0.0	0.658	0.64	0.04648	0.0	0
GC	5754	5761
data	1	3	posttyper	single	-1	--	557.544612	0.0	540.818	530.637	89.028848	-12.2518	7
data	1	3	posttyper	total	-1	--	557.544612	0.0	540.818	530.637	89.028848	-12.2518	7
data	1	4	sbt-api	single	-1	--	0.24877	0.0	0.237	0.22	0.017992	0.0	0
data	1	4	sbt-api	total	-1	--	0.24877	0.0	0.237	0.22	0.017992	0.0	0
data	1	5	pickler	single	-1	--	430.161938	0.0	425.733	421.778	62.9018	63.771312	0
data	1	5	pickler	total	-1	--	430.161938	0.0	425.733	421.778	62.9018	63.771312	0
data	1	6	linkAll	single	-1	--	0.052752	0.0	0.05	0.045	2.88E-4	0.0	0
data	1	6	linkAll	total	-1	--	0.052752	0.0	0.05	0.045	2.88E-4	0.0	0
data	1	7	reifyQuotes	single	-1	--	0.160553	0.0	0.108	0.099	0.017992	0.0	0
data	1	7	reifyQuotes	total	-1	--	0.160553	0.0	0.108	0.099	0.017992	0.0	0
data	1	8	MegaPhase{firstTransform checkReentrant elimPackagePrefixes}	single	-1	--	119.082281	0.0	117.182	112.672	13.74704	12.060256	0
data	1	8	MegaPhase{firstTransform checkReentrant elimPackagePrefixes}	total	-1	--	119.082281	0.0	117.182	112.672	13.74704	12.060256	0
GC	6790	6799
data	1	11	MegaPhase{checkStatic elimRepeated normalizeFlags extmethods expandSAMs tailrec byNameClosures liftTry hoistSuperArgs classOf refchecks}	single	-1	--	742.177615	0.0	722.95	713.693	109.079664	-41.407032	9
data	1	11	MegaPhase{checkStatic elimRepeated normalizeFlags extmethods expandSAMs tailrec byNameClosures liftTry hoistSuperArgs classOf refchecks}	total	-1	--	742.177615	0.0	722.95	713.693	109.079664	-41.407032	9
data	1	22	MegaPhase{tryCatchPatterns patternMatcher explicitOuter explicitSelf shortcutImplicits crossCast splitter}	single	-1	--	266.784142	0.0	264.767	261.447	32.549312	33.305592	0
data	1	22	MegaPhase{tryCatchPatterns patternMatcher explicitOuter explicitSelf shortcutImplicits crossCast splitter}	total	-1	--	266.784142	0.0	264.767	261.447	32.549312	33.305592	0
GC	7805	7820
data	1	29	MegaPhase{phantomArgLift vcInlineMethods seqLiterals intercepted getters elimByName elimOuterSelect augmentScala2Traits resolveSuper simplify primitiveForwarders functionXXLForwarders arrayConstructors}	single	-1	--	787.891714	0.0	767.049	763.685	189.938016	44.358072	15
data	1	29	MegaPhase{phantomArgLift vcInlineMethods seqLiterals intercepted getters elimByName elimOuterSelect augmentScala2Traits resolveSuper simplify primitiveForwarders functionXXLForwarders arrayConstructors}	total	-1	--	787.891714	0.0	767.049	763.685	189.938016	44.358072	15
GC	8765	8787
data	1	42	erasure	single	-1	--	670.471219	0.0	645.749	633.389	96.653456	-93.25196	22
data	1	42	erasure	total	-1	--	670.471219	0.0	645.749	633.389	96.653456	-93.25196	22
data	1	43	MegaPhase{elimErasedValueType vcElideAllocations mixin LazyVals memoize nonLocalReturns capturedVars}	single	-1	--	244.434858	0.0	241.999	240.459	41.836272	40.65344	0
data	1	43	MegaPhase{elimErasedValueType vcElideAllocations mixin LazyVals memoize nonLocalReturns capturedVars}	total	-1	--	244.434858	0.0	241.999	240.459	41.836272	40.65344	0
data	1	50	MegaPhase{constructors functionalInterfaces getClass simplify}	single	-1	--	72.341639	0.0	70.383	69.757	13.044904	12.196136	0
data	1	50	MegaPhase{constructors functionalInterfaces getClass simplify}	total	-1	--	72.341639	0.0	70.383	69.757	13.044904	12.196136	0
data	1	54	MegaPhase{linkScala2Impls lambdaLift elimStaticThis}	single	-1	--	206.667862	0.0	204.753	203.484	18.950736	20.426696	0
data	1	54	MegaPhase{linkScala2Impls lambdaLift elimStaticThis}	total	-1	--	206.667862	0.0	204.753	203.484	18.950736	20.426696	0
data	1	57	MegaPhase{flatten restoreScopes renameLifted transformWildcards moveStatic expandPrivate selectStatic collectEntryPoints collectSuperCalls dropInlined labelDef}	single	-1	--	188.99775	0.0	186.391	185.324	22.758184	20.326536	0
data	1	57	MegaPhase{flatten restoreScopes renameLifted transformWildcards moveStatic expandPrivate selectStatic collectEntryPoints collectSuperCalls dropInlined labelDef}	total	-1	--	188.99775	0.0	186.391	185.324	22.758184	20.326536	0
GC	10390	10414
GC	11871	11891
data	1	68	genBCode	single	-1	--	2118.290534	0.0	2027.212	1869.734	300.357288	-124.880048	44
data	1	68	genBCode	total	-1	--	2118.290534	0.0	2027.212	1869.734	300.357288	-124.880048	44

[smarter]

The "single" and "total" lines in your table are identical

[nicolasstucki]

That is the format that it produces. I guess it would be possible to have multiple runs on the same phase and then the total would be different.

[smarter]

Isn't total supposed to be the total of all phases until now?

[nicolasstucki]

The same is printed by scalac

[smarter]

Just as you're doing this PR, changes are happening on the scalac side: scala/scala#6264 :).

[mkeskells]

You have missed some other changes - scala/scala#6264 is an extra column but I think that you are missing scala/scala#6200

total ( now removed) was the total including background threads created via the async helper - but you will not get any until you get the backend chnages in scala/scala#6124 which is not merged

[nicolasstucki]

Now it looks like

info	1	version	2	output	/Users/nicolasstucki/GitHub/dotty/out/from-tasty-tmp4967691115138478341/from-source
header(main/background)	startNs	endNs	runId	phaseId	phaseName	purpose	task-count	threadId	threadName	runNs	idleNs	cpuTimeNs	userTimeNs	allocatedByte	heapSize
header(GC)	startNs	endNs	startMs	endMs	name	action	cause	threads
main	14076657448931	14078748292475	1	1	frontend		0	1	main	2090843544	0	1453538000	1423307000	57639400	84806712
main	14078751226917	14078751792525	1	2	sbt-deps		0	1	main	565608	0	564000	551000	28936	84806712
GC	14079042666396	14079049666396	3343	3349	PS Scavenge	end of minor GC	Allocation Failure	8
main	14078751951584	14079077484162	1	3	posttyper		0	1	main	325532578	0	146008000	143893000	7245560	35339528
main	14079077640892	14079077714262	1	4	sbt-api		0	1	main	73370	0	72000	68000	448	35339528
main	14079077801683	14079320063768	1	5	pickler		0	1	main	242262085	0	172941000	167897000	5503424	41151584
main	14079320222581	14079320270752	1	6	linkAll		0	1	main	48171	0	46000	41000	216	41151584
main	14079320341356	14079320382208	1	7	reifyQuotes		0	1	main	40852	0	41000	37000	448	41151584
main	14079320446604	14079350524274	1	8	MegaPhase{firstTransform  checkReentrant  elimPackagePrefixes}		0	1	main	30077670	0	26005000	25735000	1226144	42489200
main	14079354608998	14079467791736	1	11	MegaPhase{checkStatic  elimRepeated  normalizeFlags  extmethods  expandSAMs  tailrec  byNameClosures  liftTry  hoistSuperArgs  classOf  refchecks}		0	1	main	113182738	0	92340000	90856000	4391064	46502072
main	14079467948079	14079489007151	1	22	MegaPhase{tryCatchPatterns  patternMatcher  explicitOuter  explicitSelf  shortcutImplicits  crossCast  splitter}		0	1	main	21059072	0	19798000	19450000	1374664	47839784
main	14079489160953	14079543388064	1	29	MegaPhase{phantomArgLift  vcInlineMethods  seqLiterals  intercepted  getters  elimByName  elimOuterSelect  augmentScala2Traits  resolveSuper  simplify  primitiveForwarders  functionXXLForwarders  arrayConstructors}		0	1	main	54227111	0	50794000	49694000	2372208	50515016
main	14079543590522	14079724392852	1	42	erasure		0	1	main	180802330	0	168758000	166412000	10367864	61216016
GC	14079849512247	14079857512247	4064	4071	PS Scavenge	end of minor GC	Metadata GC Threshold	8
GC	14079750278593	14079858278593	4071	4178	PS MarkSweep	end of major GC	Metadata GC Threshold	8
main	14079724514915	14079894324599	1	43	MegaPhase{elimErasedValueType  vcElideAllocations  mixin  lazyVals  memoize  nonLocalReturns  capturedVars}		0	1	main	169809684	0	48149000	46308000	3961168	35518384
main	14079894436829	14079907278266	1	50	MegaPhase{constructors  functionalInterfaces  getClass  simplify}		0	1	main	12841437	0	11989000	11625000	673640	37733808
main	14079907392221	14079937216043	1	54	MegaPhase{linkScala2Impls  lambdaLift  elimStaticThis}		0	1	main	29823822	0	26652000	26061000	1244384	38456296
main	14079937343808	14079955492503	1	57	MegaPhase{flatten  restoreScopes  renameLifted  transformWildcards  moveStatic  expandPrivate  selectStatic  collectEntryPoints  collectSuperCalls  dropInlined  labelDef}		0	1	main	18148695	0	15557000	15108000	1075088	40671720
main	14079955597766	14080365285880	1	68	genBCode		0	1	main	409688114	0	394591000	383438000	30648992	69472432