AndreasSystemProfiler wrongly presents time distribution across tallies

[JanBliznicenko]

AndreasSystemProfiles seems to wrongly distribute time across the tallies.

I wanted to show the time difference between doing large string concatenation using , and using streams, by using profiler. While the AndreasSystemProfiler shows correct total time, its distribution of the time across the tallies seems to be completely wrong.

Following image shows a comparison between two scripts. On top:

|string|
string := ''.
50000 timesRepeat: [ string := string , Date today year asString ].

and at the bottom:

|string stream|
string := String streamContents: [:stream | 
	50000 timesRepeat: [ stream << Date today year asString ] 
	].

And between AndreasSystemProfiler on the left and TimeProfiler on the right.

As you can see, AndreasSystemProfiler thinks that because of string concatenation, Date today took much more time, although it does not make any sense and TimeProfiler does not think that either.

Tested in Pharo 12 build 1217 sha 7274219.

[guillep]

Thanks @JanBliznicenko. Just to add some more information here:

• it's interesting the sampling mechanism never gets the #, message which is not in the profile!
• The difference in time execution is clearly in the GC, which is attributed to one of the nodes, and unfortunately in this case always to the same node (Date>>today)

[guillep]

Assuming that in my mac the gc time precision is in milliseconds, and the profiler ticks are always in nanoseconds

runProfilerProcess
	"Run the profiler process"
	| process tallyStart tallyTicks tallyStop method leaf |
	tallyRoot := QSystemTally new class: nil method: nil.
	totalTally := 0.
	Smalltalk profileSemaphore: semaphore.
	totalTicks := 0.
	tallyStart := tallyStop := Smalltalk highResClock.
	[ true ] whileTrue: [ | gcTimeBefore totalGCTime |
		tallyStart := tallyStop.
		tallyStart := Smalltalk highResClock.
		gcTimeBefore := Smalltalk vm totalGCTime. "HERE"
		Smalltalk profileStart: ticks. "run for n ticks"
		semaphore wait.
		tallyStop := Smalltalk highResClock.
		totalGCTime := (gcTimeBefore - Smalltalk vm totalGCTime) * 1000000. "HERE"
		tallyTicks := tallyStop - tallyStart - totalGCTime. "HERE"
		totalTicks := totalTicks + tallyTicks.
		process := Smalltalk profileSample.
		method := Smalltalk profilePrimitive.
		totalTally := totalTally + 1.
		process ifNotNil:[
			leaf := tallyRoot tally: (process suspendedContext ifNil: [ thisContext ] ) by: tallyTicks.
			method ifNotNil: [ leaf tallyMethod: method by: tallyTicks ].
		].
	]

Then we have times that make more sense (although the total GC time is hidden and should probably be shown in the tree somehow)

[guillep]

To me it's definitely a profiler bug to attribute GC time to some random node.

[Ducasse]

BTW I do not understand what this highresclock as anything to do with a namespace or related.