The Inbox: Chronology-Core-mt.50.mcz
Locked
 
|
A new version of Chronology-Core was added to project The Inbox:
http://source.squeak.org/inbox/Chronology-Core-mt.50.mcz ==================== Summary ==================== Name: Chronology-Core-mt.50 Author: mt Time: 30 October 2019, 10:25:14.294226 am UUID: f064aadc-0e62-174e-b97c-f70cc22a23f6 Ancestors: Chronology-Core-mt.49 Proposal to add GC pressure to #bench method. =============== Diff against Chronology-Core-mt.49 =============== Item was changed: ----- Method: BlockClosure>>benchFor: (in category '*chronology-core') ----- benchFor: aDuration "See how many times I can value within the given duration. I'll answer a meaningful description." + | startTime shouldRun count elapsedTime roundTo3Digits delay gcStart gcTime | - | startTime shouldRun count elapsedTime roundTo3Digits delay | roundTo3Digits := [:num | | rounded lowDigit | rounded := (num * 1000) rounded. "round to 1/1000" lowDigit := (rounded numberOfDigitsInBase: 10) - 3. "keep only first 3 digits" rounded := rounded roundTo:(10 raisedTo: lowDigit). (lowDigit >= 3 or: [rounded \\ 1000 = 0]) "display fractional part only when needed" ifTrue: [(rounded // 1000) asStringWithCommas] ifFalse: [(rounded / 1000.0) printString]]. delay := aDuration asDelay. count := 0. shouldRun := true. + Smalltalk garbageCollect. [ delay wait. shouldRun := false ] forkAt: Processor timingPriority - 1. startTime := Time millisecondClockValue. + gcStart := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10). [ shouldRun ] whileTrue: [ self value. count := count + 1 ]. elapsedTime := Time millisecondsSince: startTime. + gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. ^(roundTo3Digits value: count * 1000 / elapsedTime) , ' per second.', (( #( (1e-3 'seconds') (1 'milliseconds') (1e3 'microseconds') (1e6 'nanoseconds') ) detect: [ :pair | elapsedTime * pair first >= count ] ifNone: [ #(1e9 'picoseconds') ]) in: [ :pair | ' {1} {2} per run.' format: { (roundTo3Digits value: elapsedTime * pair first / count). + pair second } ]), (' {1} % GC time.' format: {gcTime / elapsedTime * 100 roundTo: 0.0001})! - pair second } ])! |
Re: The Inbox: Chronology-Core-mt.50.mcz
|
[Error] bench '217,000,000 per second. 4.62 nanoseconds per run. 0.16 % GC time.' [Error, Halt] bench '10,400,000 per second. 96.5 nanoseconds per run. 6.2 % GC time.' [Error, Halt, Warning] bench '9,800,000 per second. 102 nanoseconds per run. 7.78 % GC time.' Best, Marcel
|
Re: The Inbox: Chronology-Core-mt.50.mcz
|
|
We probably should introduce something like that
gcTimings ^ (Smalltalk getVMParameters at: 8 "full") + (Smalltalk getVMParameters at: 10 "incr") Best regards -Tobias > On 30.10.2019, at 10:27, Marcel Taeumel <[hidden email]> wrote: > > [Error] bench > '217,000,000 per second. 4.62 nanoseconds per run. 0.16 % GC time.' > [Error, Halt] bench > '10,400,000 per second. 96.5 nanoseconds per run. 6.2 % GC time.' > [Error, Halt, Warning] bench > '9,800,000 per second. 102 nanoseconds per run. 7.78 % GC time.' > > Best, > Marcel >> Am 30.10.2019 10:25:21 schrieb [hidden email] <[hidden email]>: >> >> A new version of Chronology-Core was added to project The Inbox: >> http://source.squeak.org/inbox/Chronology-Core-mt.50.mcz >> >> ==================== Summary ==================== >> >> Name: Chronology-Core-mt.50 >> Author: mt >> Time: 30 October 2019, 10:25:14.294226 am >> UUID: f064aadc-0e62-174e-b97c-f70cc22a23f6 >> Ancestors: Chronology-Core-mt.49 >> >> Proposal to add GC pressure to #bench method. >> >> =============== Diff against Chronology-Core-mt.49 =============== >> >> Item was changed: >> ----- Method: BlockClosure>>benchFor: (in category '*chronology-core') ----- >> benchFor: aDuration >> "See how many times I can value within the given duration. I'll answer a meaningful description." >> >> + | startTime shouldRun count elapsedTime roundTo3Digits delay gcStart gcTime | >> - | startTime shouldRun count elapsedTime roundTo3Digits delay | >> roundTo3Digits := [:num | >> | rounded lowDigit | >> rounded := (num * 1000) rounded. "round to 1/1000" >> lowDigit := (rounded numberOfDigitsInBase: 10) - 3. "keep only first 3 digits" >> rounded := rounded roundTo:(10 raisedTo: lowDigit). >> (lowDigit >= 3 or: [rounded \\ 1000 = 0]) "display fractional part only when needed" >> ifTrue: [(rounded // 1000) asStringWithCommas] >> ifFalse: [(rounded / 1000.0) printString]]. >> delay := aDuration asDelay. >> count := 0. >> shouldRun := true. >> + Smalltalk garbageCollect. >> [ delay wait. shouldRun := false ] forkAt: Processor timingPriority - 1. >> startTime := Time millisecondClockValue. >> + gcStart := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10). >> [ shouldRun ] whileTrue: [ >> self value. >> count := count + 1 ]. >> elapsedTime := Time millisecondsSince: startTime. >> + gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. >> ^(roundTo3Digits value: count * 1000 / elapsedTime) , ' per second.', (( >> #( >> (1e-3 'seconds') >> (1 'milliseconds') >> (1e3 'microseconds') >> (1e6 'nanoseconds') >> ) >> detect: [ :pair | elapsedTime * pair first >= count ] >> ifNone: [ #(1e9 'picoseconds') ]) >> in: [ :pair | >> ' {1} {2} per run.' format: { >> (roundTo3Digits value: elapsedTime * pair first / count). >> + pair second } ]), (' {1} % GC time.' format: {gcTime / elapsedTime * 100 roundTo: 0.0001})! >> - pair second } ])! >> >> > |
Re: The Inbox: Chronology-Core-mt.50.mcz
|
|
+1 for inclusion, with the following suggested tweak:
Use printShowingMaxDecimalPlaces: rather than roundTo: in the percent GC display, and also drop the space before the $%. Thus the last line of the method would be: pair second } ]), (' {1}% GC time.' format: {gcTime / elapsedTime * 100 printShowingMaxDecimalPlaces: 5}) Rationale: Rounding may not do what you expect with some float calculations. This may be VM dependent (I can explain in a separate follow up message), but for example I saw occasional results like this: '85,200 per second. 11.7 microseconds per run. 2.3850000000000002 % GC time.' Using printShowingMaxDecimalPlaces: will ensure this instead: '85,200 per second. 11.7 microseconds per run. 2.385% GC time.' Dave On Wed, Oct 30, 2019 at 11:13:41AM +0100, Tobias Pape wrote: > We probably should introduce something like that > > > gcTimings > > ^ (Smalltalk getVMParameters at: 8 "full") + > (Smalltalk getVMParameters at: 10 "incr") > > > Best regards > -Tobias > > On 30.10.2019, at 10:27, Marcel Taeumel <[hidden email]> wrote: > > > > [Error] bench > > '217,000,000 per second. 4.62 nanoseconds per run. 0.16 % GC time.' > > [Error, Halt] bench > > '10,400,000 per second. 96.5 nanoseconds per run. 6.2 % GC time.' > > [Error, Halt, Warning] bench > > '9,800,000 per second. 102 nanoseconds per run. 7.78 % GC time.' > > > > Best, > > Marcel > >> Am 30.10.2019 10:25:21 schrieb [hidden email] <[hidden email]>: > >> > >> A new version of Chronology-Core was added to project The Inbox: > >> http://source.squeak.org/inbox/Chronology-Core-mt.50.mcz > >> > >> ==================== Summary ==================== > >> > >> Name: Chronology-Core-mt.50 > >> Author: mt > >> Time: 30 October 2019, 10:25:14.294226 am > >> UUID: f064aadc-0e62-174e-b97c-f70cc22a23f6 > >> Ancestors: Chronology-Core-mt.49 > >> > >> Proposal to add GC pressure to #bench method. > >> > >> =============== Diff against Chronology-Core-mt.49 =============== > >> > >> Item was changed: > >> ----- Method: BlockClosure>>benchFor: (in category '*chronology-core') ----- > >> benchFor: aDuration > >> "See how many times I can value within the given duration. I'll answer a meaningful description." > >> > >> + | startTime shouldRun count elapsedTime roundTo3Digits delay gcStart gcTime | > >> - | startTime shouldRun count elapsedTime roundTo3Digits delay | > >> roundTo3Digits := [:num | > >> | rounded lowDigit | > >> rounded := (num * 1000) rounded. "round to 1/1000" > >> lowDigit := (rounded numberOfDigitsInBase: 10) - 3. "keep only first 3 digits" > >> rounded := rounded roundTo:(10 raisedTo: lowDigit). > >> (lowDigit >= 3 or: [rounded \\ 1000 = 0]) "display fractional part only when needed" > >> ifTrue: [(rounded // 1000) asStringWithCommas] > >> ifFalse: [(rounded / 1000.0) printString]]. > >> delay := aDuration asDelay. > >> count := 0. > >> shouldRun := true. > >> + Smalltalk garbageCollect. > >> [ delay wait. shouldRun := false ] forkAt: Processor timingPriority - 1. > >> startTime := Time millisecondClockValue. > >> + gcStart := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10). > >> [ shouldRun ] whileTrue: [ > >> self value. > >> count := count + 1 ]. > >> elapsedTime := Time millisecondsSince: startTime. > >> + gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. > >> ^(roundTo3Digits value: count * 1000 / elapsedTime) , ' per second.', (( > >> #( > >> (1e-3 'seconds') > >> (1 'milliseconds') > >> (1e3 'microseconds') > >> (1e6 'nanoseconds') > >> ) > >> detect: [ :pair | elapsedTime * pair first >= count ] > >> ifNone: [ #(1e9 'picoseconds') ]) > >> in: [ :pair | > >> ' {1} {2} per run.' format: { > >> (roundTo3Digits value: elapsedTime * pair first / count). > >> + pair second } ]), (' {1} % GC time.' format: {gcTime / elapsedTime * 100 roundTo: 0.0001})! > >> - pair second } ])! > >> > >> > > > > > |
Precision of VM parameters 8, 10, 36, and 38 for GC statistics (was: The Inbox: Chronology-Core-mt.50.mcz)
|
|
Keeping this on squeak-dev because it it pertains to semantics and
usage in Squeak as opposed to how to implement it in the VM. I propose that the VMs should report GC metrics as millisecond values with microsecond precision, and the Float return values be used to implement this when the values are not whole milliseconds. Mainly this affects the interpreter VM but would also be beneficial for Cog/Spur to make the higher precision measurements accessible. A Squeak Float can be conveniently returned by a primitive, and has magnitude sufficient for five hours worth of microseconds. Comments welcome, and I'll put the implementation into the interpreter VM if no one objects. I can add it to oscog also if people like the idea. Explanation: The various VMs keep track of GC time internally to microsecond precision. The oscog VMs and SqueakJS all correctly report the VM parameters to lower millisecond precision, and the traditional interpreter VMs incorrectly report the values to microsecond precision. Here, "correct" means compliant with the documented interface in the method comments in both the VM and the image. Background: Early VMs reported GC timings in milliseconds. In January 2010, John McIntosh proposed a set of VM changes to enable microsecond timing precision in VM metrics: http://lists.squeakfoundation.org/pipermail/vm-dev/2010-January/003683.html This proposal was tracked on Mantis: http://bugs.squeak.org/view.php?id=7458 And John's changes were incorporated into the VM here: Name: VMMaker-dtl.164 Author: dtl Time: 28 March 2010, 1:44:25 pm VMMaker 4.0.1 Reference Mantis 7458: [Vm-dev] microsecond timing for GC work Add primitiveMicrosecondClock and microsecond GC instrumentation by John McIntosh. Add primitiveUtcWithOffset. Fix signature of Interpreter>>dumpImage: (pointer declared as int). The new primitives require support in the platform code. Default implementations are provided to allow compilation without these platforms updates, see CCodeGenerator>>writeDefaultMacrosOn:. Without platform updates, the GC instrumentation falls back to millisecond precision, the primitiveMicrosecondClock primitive answers (incorrectly) a millisecond value, and primitiveUtcWithOffset fails the primitive. I believe that our intention at the time was change to directly reporting these parameters in microseconds and update the method comments accordingly, but for whatever reason this didn't happen. The comments remained the same and the (interpreter) VM now reported whole microseconds rather than milliseconds for parameters 8 and 10, which conflicted with the method comments and with the original semantics. Meanwhile, Cog was progressing in the oscog branch of VMMaker and platform sources, delivering improvements for GC internals and metrics collection, but continuing to honor the documented interface for these VM parameters. This was probably done early in in the oscog development branch, as the oldest entry in the VMMaker respository (VMMaker.oscog-eem.55 from April 2011) is rounding the VM parameters 8, 10, and 38 back to the spicified millisecond precision. Now we have a well established expectation of the GC parameters being reported in milliseconds, so for example Chronology-Core-mt.50 in the inbox depends on that behavior. Changing that convention would be messy now, while it is fairly easy to allow the parameter values to take Float values when higher precision is needed. Changing all the VMs to answer millisecond values, with either integer milliseconds or Float for higher precision, will give consistent semantics. I tested an implementation for the interpreter VM, and it works well. Dave On Sat, Nov 02, 2019 at 11:15:42AM -0400, David T. Lewis wrote: > +1 for inclusion, with the following suggested tweak: > > Use printShowingMaxDecimalPlaces: rather than roundTo: in the percent > GC display, and also drop the space before the $%. Thus the last line > of the method would be: > > > pair second } ]), (' {1}% GC time.' format: {gcTime / elapsedTime * 100 printShowingMaxDecimalPlaces: 5}) > > > Rationale: Rounding may not do what you expect with some float calculations. > This may be VM dependent (I can explain in a separate follow up message), > but for example I saw occasional results like this: > > '85,200 per second. 11.7 microseconds per run. 2.3850000000000002 % GC time.' > > Using printShowingMaxDecimalPlaces: will ensure this instead: > > '85,200 per second. 11.7 microseconds per run. 2.385% GC time.' > > Dave > |
Re: The Inbox: Chronology-Core-mt.50.mcz
|
|
In reply to this post by David T. Lewis
Hi Dave, yes, that's an important tweak. I was wondering about this: ... elapsedTime := Time millisecondsSince: startTime. gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. ... How complex is #millisecondsSince:? Would it make sense to swap those lines? Given that #bench usually runs for 5 seconds and the GC time is expressed in %, this might be irrelevant... Best, Marcel
|
Re: The Inbox: Chronology-Core-mt.50.mcz
|
|
On Mon, Nov 04, 2019 at 10:05:10AM +0100, Marcel Taeumel wrote:
> Hi Dave, > > yes, that's an important tweak. > > I was wondering about this: > > ... > elapsedTime := Time millisecondsSince: startTime. > gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. > ... > > How complex is #millisecondsSince:? Would it make sense to swap those lines? Given that #bench usually runs for 5 seconds and the GC time is expressed in %, this might be irrelevant...?? > The way you wrote it is good. You might get a couple of large integers instantiated in millisecondsSince: but only on 32 bits, and the chance of that affecting the GC measurement is about zero. Besides, the two vmParameterAt: calls may instantiate objects within the primitive anyway. Dave > Best, > Marcel > Am 02.11.2019 16:15:53 schrieb David T. Lewis <[hidden email]>: > +1 for inclusion, with the following suggested tweak: > > Use printShowingMaxDecimalPlaces: rather than roundTo: in the percent > GC display, and also drop the space before the $%. Thus the last line > of the method would be: > > > pair second } ]), (' {1}% GC time.' format: {gcTime / elapsedTime * 100 printShowingMaxDecimalPlaces: 5}) > > > Rationale: Rounding may not do what you expect with some float calculations. > This may be VM dependent (I can explain in a separate follow up message), > but for example I saw occasional results like this: > > '85,200 per second. 11.7 microseconds per run. 2.3850000000000002 % GC time.' > > Using printShowingMaxDecimalPlaces: will ensure this instead: > > '85,200 per second. 11.7 microseconds per run. 2.385% GC time.' > > Dave > > > On Wed, Oct 30, 2019 at 11:13:41AM +0100, Tobias Pape wrote: > > We probably should introduce something like that > > > > > > gcTimings > > > > ^ (Smalltalk getVMParameters at: 8 "full") + > > (Smalltalk getVMParameters at: 10 "incr") > > > > > > Best regards > > -Tobias > > > On 30.10.2019, at 10:27, Marcel Taeumel wrote: > > > > > > [Error] bench > > > '217,000,000 per second. 4.62 nanoseconds per run. 0.16 % GC time.' > > > [Error, Halt] bench > > > '10,400,000 per second. 96.5 nanoseconds per run. 6.2 % GC time.' > > > [Error, Halt, Warning] bench > > > '9,800,000 per second. 102 nanoseconds per run. 7.78 % GC time.' > > > > > > Best, > > > Marcel > > >> Am 30.10.2019 10:25:21 schrieb [hidden email] : > > >> > > >> A new version of Chronology-Core was added to project The Inbox: > > >> http://source.squeak.org/inbox/Chronology-Core-mt.50.mcz > > >> > > >> ==================== Summary ==================== > > >> > > >> Name: Chronology-Core-mt.50 > > >> Author: mt > > >> Time: 30 October 2019, 10:25:14.294226 am > > >> UUID: f064aadc-0e62-174e-b97c-f70cc22a23f6 > > >> Ancestors: Chronology-Core-mt.49 > > >> > > >> Proposal to add GC pressure to #bench method. > > >> > > >> =============== Diff against Chronology-Core-mt.49 =============== > > >> > > >> Item was changed: > > >> ----- Method: BlockClosure>>benchFor: (in category '*chronology-core') ----- > > >> benchFor: aDuration > > >> "See how many times I can value within the given duration. I'll answer a meaningful description." > > >> > > >> + | startTime shouldRun count elapsedTime roundTo3Digits delay gcStart gcTime | > > >> - | startTime shouldRun count elapsedTime roundTo3Digits delay | > > >> roundTo3Digits := [:num | > > >> | rounded lowDigit | > > >> rounded := (num * 1000) rounded. "round to 1/1000" > > >> lowDigit := (rounded numberOfDigitsInBase: 10) - 3. "keep only first 3 digits" > > >> rounded := rounded roundTo:(10 raisedTo: lowDigit). > > >> (lowDigit >= 3 or: [rounded \\ 1000 = 0]) "display fractional part only when needed" > > >> ifTrue: [(rounded // 1000) asStringWithCommas] > > >> ifFalse: [(rounded / 1000.0) printString]]. > > >> delay := aDuration asDelay. > > >> count := 0. > > >> shouldRun := true. > > >> + Smalltalk garbageCollect. > > >> [ delay wait. shouldRun := false ] forkAt: Processor timingPriority - 1. > > >> startTime := Time millisecondClockValue. > > >> + gcStart := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10). > > >> [ shouldRun ] whileTrue: [ > > >> self value. > > >> count := count + 1 ]. > > >> elapsedTime := Time millisecondsSince: startTime. > > >> + gcTime := (Smalltalk vmParameterAt: 8) + (Smalltalk vmParameterAt: 10) - gcStart. > > >> ^(roundTo3Digits value: count * 1000 / elapsedTime) , ' per second.', (( > > >> #( > > >> (1e-3 'seconds') > > >> (1 'milliseconds') > > >> (1e3 'microseconds') > > >> (1e6 'nanoseconds') > > >> ) > > >> detect: [ :pair | elapsedTime * pair first >= count ] > > >> ifNone: [ #(1e9 'picoseconds') ]) > > >> in: [ :pair | > > >> ' {1} {2} per run.' format: { > > >> (roundTo3Digits value: elapsedTime * pair first / count). > > >> + pair second } ]), (' {1} % GC time.' format: {gcTime / elapsedTime * 100 roundTo: 0.0001})! > > >> - pair second } ])! > > >> > > >> > > > > > > > > > > > |
«
Return to Squeak - Dev
|
1 view|%1 views
| Free forum by Nabble | Edit this page |