.TLReliable Benchmarking with Limbo on Inferno.AUJohn BatesVita Nuova Limited.SP3rd March 1999.brRevised 20th February 2000.ABOur goal was to identify a mechanism for performingaccurate, reliable and realistic benchmarking measurementswith Limbo on Inferno.The measurements would need to be \fIaccurate\fR in the sense that we could be confident that they were sufficiently close to the real timetaken to perform the measured operation.We would consider a measurement to be \fIreliable\fR if it could be obtainedrepeatedly when carried out under the same conditions at a later date.Additionally, a measurement is only useful if it can be claimedto be related to the expected performance of a real applicable operation,we would call such a measurement \fIrealistic\fR.The emphasis in this document is on achieving a reliable measurement..AE.SHExpectation.LPWe would like to be able to make measurements with code like:.P1s := Sample.new(NREP);for(i:=0; i<NREP; i++) { t = tstamp(); sys->sleep(0); t = tstamp() - t; s.add(t-base);}.P2Where .CW sis an object that can be used to record up to.CW NREPmeasurements and.CW baseis our predetermined estimate of the cost of actually making themeasurement. The Limbo function.CW tstamp()uses \fIdevbench\fR to obtain a microsecond timestamp.Such a measurement would give us an idea of the cost of making a.CW sys->sleep(0)call and by examining a sample of such measurements we could reason aboutthe true cost of the call. In particular, we would get a feel forjust how reliable our estimate of the true cost was..LPThe first task was to determine a suitable value to use for.CW baseby measuring how long it took to do \fInothing\fR\(dg..FS.vs 9.FA\(dg This benchmark is called.CW BASEin the \fIdevbench\fR benchmark suite..FE.P1s := Sample.new(NREP);for(i:=0; i<NREP; i++) { t = tstamp(); t = tstamp() - t; s.add(t-base);}(n, mean, min, max, std) := s.stat();base = min;.P2By repeating the measurement a large number of times and then bychoosing the minimum measurement we could hope to choose asensible value for.CW base.Our confidence in the chosen value and in the results of subsequent benchmarkingwould be greatest if thedistribution of measurements was \fInarrow\fR with mostof the values close to the minimum..SHInitial Results.LPWe ran the initial tests on a 150MHz Pentium PC with a standardInferno 2.0 native kernel and later with an Inferno 2.3 native kernel.The commands.P1bench -o >xbgrep BASE x | plot.P2run the benchmark suite leaving the observations in a file called.CW xand then extract the line containing the results for the test called.CW BASEand plot them to a Wm window under Inferno\(dg..FS.vs 9.FA\(dg Actually, to generate the graphs in this document I used plot -g whichproduces grap(1) output..br.vs.FEThe command.CW bgrepis used in place of.CW grepbecause the Inferno.CW grepuses.CW sys->printto output lines and so inherits a very small upper bound on line length.The.CW -ooption to .CW benchdelivers the individual observations rather than summary statistics.The.CW BASEtest repeats the above empty loop 1000 times.Plotting the observations in the order in which they were observedgives the surprising result shown in Figure 1..KF.G1copy "x0base.gr".G2.I "Figure 1. Showing the unexpected variation in the BASE results.".KEThe majority of values appear to be small, but the graph is dominatedby the relatively small number of very large irregular observations whichlie at around 6 milliseconds to 8 millisecondsand a clearly discernible second set of valueswhich look to form a more regular pattern at aboutthe 1 millisecond level.The smaller set of values can be seen more clearly by removing thelarge values and rescaling the graph.The.CW -ooption to.CW Plotinvokes a crude scheme to remove a layer of outliers.It does this by calculating the sample mean and standard deviation and removing values which lie more than two standard deviations away from the mean. The process is repeated for each occurrence of the.CW -ooption to.CW plot.Thus.P1plot -ooo.P2will remove three layers of outliers and then plot the remaining values..KSRunning.P1bgrep BASE x | plot -o.P2gives the output shown in figure 2..KE.KF.G1copy "x0baseo.gr".G2.I "Figure 2. Great variability in the BASE results, \even with the large outliers removed.".KEAgain, a large number of small values (less than 500 microseconds)and a smaller number of larger values lying at around about the 1 millisecondlevel.Running the commands.P1bgrep BASE x | plot -p 1hbgrep BASE x | plot -p 1h -o -z.P2gives a histogram showing the distribution of the results.Firstly, with all the valuesand then with one level of outliers removed \(dg..FS.vs 9.FA\(dg The.CW -zoption to \fIplot\fR forces a zero origin to be part of the plot..FE.KF.G1copy "x0baseh.gr".G2.I "Figure 3. Histogram showing the distribution of results \from the BASE benchmark.".KEIn Figure 3 we can see a small set of values up above the 7 millisecondlevel and then a slightly more focused set at around about 1 millisecond buttogether these groups make up much less than 10% of the total values..KF.G1copy "x0baseho.gr".G2.I "Figure 4. Histogram showing the distribution of results \from the BASE benchmark with the large outliers removed.".KEBy removing a level of outliers we can see the distribution of thelower values more clearly, as shown in Figure 4.Even this lower cluster ranges from about 220 microseconds up toabout 500 microseconds..LPWe can conclude from these initial resultsthat it is not going to be possible to use this mechanism toperform accurate or reliable benchmarking unless its performancecan be improved..SHThe Measurement Process.LPAt this stage we're not actually measuring anything real, but lookingto obtain some confidence in our measurements.We have started by observing times to complete the measurement of\fInothing\fR. We do this by writing a Limbo program (\fIbench.b\fR)which contains the following code:.P1t0, t1, base: big;NREP: con 1000; s := Sample.new(NREP);treset();for(i:=0; i<NREP; i++) { t0 = tstamp(); t1 = tstamp(); s.add(t1-t0);}(nil, nil, base, nil, nil) = s.stat(); iob.puts("BASE:1l:Observation::Time:us ");s.obs(iob);iob.puts("\\n");iob.flush();.P2The middle section of code performs the benchmark by takingtwo consecutive timestamps and noting the difference between them.This is repeated 1000 times and the observations accumulatedin the sample variable.CW s.The function.CW s.stat()returns a tuple containing count, mean, minimum, maximumand standard deviation for the accumulated values.We assign the minimum value to our variable.CW base.The function.CW treset()arranges for the timestamp code to start returningsmall values and so reduces the likelihood of overflowor signing related issues..LPThe last section of code outputs one line containing the individualobservations separated by spaces and with a suitably formattedinitial \fIword\fR which labels the line so that.CW plotcan make a useful interpretation of the results..KS.LPThe functions.CW treset()and.CW tstamp()make use of files served by \fIdevbench\fR and look like this:.P1tsfd: ref Sys->FD;treset(){ tsfd = sys->open("/dev/busec", sys->OWRITE); if(tsfd == nil) return; buf := array[1] of byte; n := sys->write(tsfd, buf, len buf); tsfd = sys->open("/dev/busec", sys->OREAD);}.P3tstamp(): big{ buf := array[128] of byte; n := sys->read(tsfd, buf, len buf); if(n < 0) return big 0; return big string buf[0:n];}.P2.KE\fIDevbench\fR must have been previously bound into thenamespace.P1bind -b '#x' /dev.P2so that the files.P1/dev/bctl/dev/bdata/dev/busec.P2are available.A microsecond timestamp is provided by reading from.CW /dev/busecand is reset to zero each time anthing is written to it.The function.CW treset()resets the timestamp by writing to the file and then opens it for reading.The function.CW tstamp()reads the timestamp from the file and converts it into a.CW bigvalue for use in the program.The device driver ignores the offset when reading from the file so that itis not necessary to.CW seekto the beginning of the file before each read.The important part of the benchmark consists of two consecutive calls to.CW tstamp().We need to identify where time is being spent; either in the calls to.CW tstamp()or else inside the function itself..SHCosting.LPThe \fIdevbench\fR suite of programs includes one for timingindividual lines of Limbo code and breaking down the timespent on each line into times for each of the Dis operationsinvoked by that line; the program is called \fIcost\fR.To find out how long each part of the benchmark timing looptakes we can invoke.P1cost -f bench.b -s bench.P2Which results in the following output - edited to justshow the timing loop and the function.CW tstamp()\&.The first line is the output from \fIbench\fR giving themean, minimum, maximum and standard deviation of microsecond times for1000 repetitions of the loop. We see a minimum of 402 microsecondsand a maximum of just over 9 milliseconds.The remaining lines are the output of \fIcost\fR; those beginningwith a dash are Dis operation times for the preceding Limbosource code line. Dis operation lines contain an operation name,an execution count and the mean, minimum, maximum andstandard deviation of execution times..P1BASE:summary:Sample:n:Time:us 1000 486 402 9053 499 -- bench.b\&... treset();- frame 1 2.13 us 2.13 us 2.13 us 0 ns- call 1 807 ns 807 ns 807 ns 0 ns s := Sample.new(NREP*10);- mframe 1 4.85 us 4.85 us 4.85 us 0 ns- movw 1 2.27 us 2.27 us 2.27 us 0 ns- lea 1 1.57 us 1.57 us 1.57 us 0 ns- mcall 1 2.71 us 2.71 us 2.71 us 0 ns for(i:=0; i<NREP*10; i++) {- movw 1 1.99 us 1.99 us 1.99 us 0 ns- blew 1001 1.60 us 1.51 us 34.04 us 1.03 us t0 = tstamp();- frame 1000 2.43 us 2.29 us 3.40 us 133 ns- lea 1000 1.00 us 953 ns 27.74 us 847 ns- call 1000 1.45 us 1.29 us 2.24 us 153 ns t1 = tstamp();- frame 1000 3.45 us 3.01 us 5.57 us 293 ns- lea 1000 1.22 us 1.02 us 1.61 us 173 ns- call 1000 1.44 us 1.29 us 1.75 us 140 ns s.add(t1-t0);- mframe 1000 3.65 us 3.37 us 24.73 us 700 ns- movp 1000 1.99 us 1.48 us 2.96 us 267 ns- subl 1000 2.43 us 2.23 us 4.80 us 173 ns- mcall 1000 2.11 us 1.95 us 2.51 us 120 ns- addw 1000 1.62 us 1.48 us 2.50 us 127 ns- jmp 1000 1.50 us 1.37 us 1.81 us 120 ns } (nil, nil, base, nil, nil) = s.stat();- mframe 1 2.66 us 2.66 us 2.66 us 0 ns- movp 1 1.39 us 1.39 us 1.39 us 0 ns- lea 1 1.41 us 1.41 us 1.41 us 0 ns- mcall 1 1.37 us 1.37 us 1.37 us 0 ns- movl 1 1.56 us 1.56 us 1.56 us 0 ns if(sflag)- beqw 1 2.14 us 2.14 us 2.14 us 0 ns iob.puts("BASE:summary:Sample:n:Time:us " + s.str() + "\\n");- mframe 1 4.01 us 4.01 us 4.01 us 0 ns- movp 1 2.87 us 2.87 us 2.87 us 0 ns- mframe 1 1.75 us 1.75 us 1.75 us 0 ns- movp 1 1.69 us 1.69 us 1.69 us 0 ns- lea 1 1.15 us 1.15 us 1.15 us 0 ns- mcall 1 2.35 us 2.35 us 2.35 us 0 ns- addc 1 19.57 us 19.57 us 19.57 us 0 ns- addc 1 8.55 us 8.55 us 8.55 us 0 ns- lea 1 1.49 us 1.49 us 1.49 us 0 ns- mcall 1 3.65 us 3.65 us 3.65 us 0 ns iob.flush();- mframe 1 4.50 us 4.50 us 4.50 us 0 ns- movp 1 2.13 us 2.13 us 2.13 us 0 ns- lea 1 967 ns 967 ns 967 ns 0 ns- mcall 1 1.89 us 1.89 us 1.89 us 0 ns }\&....P3 # return timestamp in microsecondststamp(): big{ buf := array[128] of byte;- newa 2000 6.98 us 5.37 us 80.91 us 2.43 us n := sys->read(tsfd, buf, len buf);- mframe 2000 3.05 us 2.59 us 4.05 us 227 ns- movp 2000 2.33 us 2.14 us 3.21 us 120 ns- movp 2000 1.19 us 1.14 us 2.93 us 73 ns- lena 2000 1.07 us 907 ns 34.48 us 760 ns- lea 2000 893 ns 860 ns 33.00 us 907 ns- mcall 2000 133.81 us 89.88 us 8.61 ms 514.44 us if(n < 0)- blew 2000 2.27 us 1.76 us 3.43 us 313 ns return big 0; return big string buf[0:n];- movp 2000 2.21 us 1.67 us 3.38 us 253 ns- slicea 2000 10.06 us 8.35 us 39.31 us 1.40 us- cvtac 2000 12.02 us 11.13 us 16.63 us 553 ns- cvtcl 2000 16.39 us 15.78 us 45.16 us 787 ns- ret 2000 10.52 us 9.79 us 13.97 us 333 ns}.P2We can see from these figures that times for both callsto.CW tstamp()are reasonably low. But looking at the call to.CW "sys->read()"in .CW tstamp()we can see a maximum of just over 8½ milliseconds for the \fImcall\fRoperation. We see too that this operation also has a high standard deviationof 514 microseconds across 2000 calls and so it looks like it may bethe cause of the large observed delays..LPIn order to get a second view of what was happening we surrounded thetiming code with calls to enable kernel profiling..P1profon();for(i:=0; i<NREP*10; i++) { t0 = tstamp(); t1 = tstamp(); s.add(t1-t0);}profoff();\&...profon(){ if(sys->write(kpctl, array of byte "startclr", 8) < 8) error("kprof start");} profoff(){ if(sys->write(kpctl, array of byte "stop", 4) < 4) error("kprof stop");}.P2Having previously bound in \fIdevkprof\fR.P1bind -b '#T' /dev.P2and opened \fI/dev/kpctl\fR for writing.By examining the contents of \fI/dev/kpdata\fR with \fIkprof\fRwe see that the garbage collection functions \fImarkheap\fRand \fIrungc\fR are taking up a surprisingly large amountof kernel time for this operation..P1total: 1460 in kernel text: 1460 outside kernel text: 0KTZERO 80100000ms % sym130 8.9 markheap110 7.5 iunlock100 6.8 xec90 6.1 rungc80 5.4 chartorune70 4.7 c2string60 4.1 numbconv50 3.4 string2c40 2.7 sched40 2.7 wakeup30 2.0 splhi30 2.0 freeptrs30 2.0 memset30 2.0 dodiv30 2.0 _divvu30 2.0 strtoll20 1.3 _mulv20 1.3 vmachine20 1.3 unlock20 1.3 runproc20 1.3 DEA10 0.6 kwriteLines 1–500 of 982. Load more
.TL Reliable Benchmarking with Limbo on Inferno .AU John Bates Vita Nuova Limited .SP 3rd March 1999 .br Revised 20th February 2000 .AB Our goal was to identify a mechanism for performing accurate, reliable and realistic benchmarking measurements with Limbo on Inferno. The measurements would need to be \fIaccurate\fR in the sense that we could be confident that they were sufficiently close to the real time taken to perform the measured operation. We would consider a measurement to be \fIreliable\fR if it could be obtained repeatedly when carried out under the same conditions at a later date. Additionally, a measurement is only useful if it can be claimed to be related to the expected performance of a real applicable operation, we would call such a measurement \fIrealistic\fR. The emphasis in this document is on achieving a reliable measurement. .AE .SH Expectation .LP We would like to be able to make measurements with code like: .P1 s := Sample.new(NREP); for(i:=0; i<NREP; i++) { t = tstamp(); sys->sleep(0); t = tstamp() - t; s.add(t-base); } .P2 Where .CW s is an object that can be used to record up to .CW NREP measurements and .CW base is our predetermined estimate of the cost of actually making the measurement. The Limbo function .CW tstamp() uses \fIdevbench\fR to obtain a microsecond timestamp. Such a measurement would give us an idea of the cost of making a .CW sys->sleep(0) call and by examining a sample of such measurements we could reason about the true cost of the call. In particular, we would get a feel for just how reliable our estimate of the true cost was. .LP The first task was to determine a suitable value to use for .CW base by measuring how long it took to do \fInothing\fR\(dg. .FS .vs 9 .FA \(dg This benchmark is called .CW BASE in the \fIdevbench\fR benchmark suite. .FE .P1 s := Sample.new(NREP); for(i:=0; i<NREP; i++) { t = tstamp(); t = tstamp() - t; s.add(t-base); } (n, mean, min, max, std) := s.stat(); base = min; .P2 By repeating the measurement a large number of times and then by choosing the minimum measurement we could hope to choose a sensible value for .CW base. Our confidence in the chosen value and in the results of subsequent benchmarking would be greatest if the distribution of measurements was \fInarrow\fR with most of the values close to the minimum. .SH Initial Results .LP We ran the initial tests on a 150MHz Pentium PC with a standard Inferno 2.0 native kernel and later with an Inferno 2.3 native kernel. The commands .P1 bench -o >x bgrep BASE x | plot .P2 run the benchmark suite leaving the observations in a file called .CW x and then extract the line containing the results for the test called .CW BASE and plot them to a Wm window under Inferno\(dg. .FS .vs 9 .FA \(dg Actually, to generate the graphs in this document I used plot -g which produces grap(1) output. .br .vs .FE The command .CW bgrep is used in place of .CW grep because the Inferno .CW grep uses .CW sys->print to output lines and so inherits a very small upper bound on line length. The .CW -o option to .CW bench delivers the individual observations rather than summary statistics. The .CW BASE test repeats the above empty loop 1000 times. Plotting the observations in the order in which they were observed gives the surprising result shown in Figure 1. .KF .G1 copy "x0base.gr" .G2 .I "Figure 1. Showing the unexpected variation in the BASE results." .KE The majority of values appear to be small, but the graph is dominated by the relatively small number of very large irregular observations which lie at around 6 milliseconds to 8 milliseconds and a clearly discernible second set of values which look to form a more regular pattern at about the 1 millisecond level. The smaller set of values can be seen more clearly by removing the large values and rescaling the graph. The .CW -o option to .CW Plot invokes a crude scheme to remove a layer of outliers. It does this by calculating the sample mean and standard deviation and removing values which lie more than two standard deviations away from the mean. The process is repeated for each occurrence of the .CW -o option to .CW plot. Thus .P1 plot -ooo .P2 will remove three layers of outliers and then plot the remaining values. .KS Running .P1 bgrep BASE x | plot -o .P2 gives the output shown in figure 2. .KE .KF .G1 copy "x0baseo.gr" .G2 .I "Figure 2. Great variability in the BASE results, \ even with the large outliers removed." .KE Again, a large number of small values (less than 500 microseconds) and a smaller number of larger values lying at around about the 1 millisecond level. Running the commands .P1 bgrep BASE x | plot -p 1h bgrep BASE x | plot -p 1h -o -z .P2 gives a histogram showing the distribution of the results. Firstly, with all the values and then with one level of outliers removed \(dg. .FS .vs 9 .FA \(dg The .CW -z option to \fIplot\fR forces a zero origin to be part of the plot. .FE .KF .G1 copy "x0baseh.gr" .G2 .I "Figure 3. Histogram showing the distribution of results \ from the BASE benchmark." .KE In Figure 3 we can see a small set of values up above the 7 millisecond level and then a slightly more focused set at around about 1 millisecond but together these groups make up much less than 10% of the total values. .KF .G1 copy "x0baseho.gr" .G2 .I "Figure 4. Histogram showing the distribution of results \ from the BASE benchmark with the large outliers removed." .KE By removing a level of outliers we can see the distribution of the lower values more clearly, as shown in Figure 4. Even this lower cluster ranges from about 220 microseconds up to about 500 microseconds. .LP We can conclude from these initial results that it is not going to be possible to use this mechanism to perform accurate or reliable benchmarking unless its performance can be improved. .SH The Measurement Process .LP At this stage we're not actually measuring anything real, but looking to obtain some confidence in our measurements. We have started by observing times to complete the measurement of \fInothing\fR. We do this by writing a Limbo program (\fIbench.b\fR) which contains the following code: .P1 t0, t1, base: big; NREP: con 1000; s := Sample.new(NREP); treset(); for(i:=0; i<NREP; i++) { t0 = tstamp(); t1 = tstamp(); s.add(t1-t0); } (nil, nil, base, nil, nil) = s.stat(); iob.puts("BASE:1l:Observation::Time:us "); s.obs(iob); iob.puts("\\n"); iob.flush(); .P2 The middle section of code performs the benchmark by taking two consecutive timestamps and noting the difference between them. This is repeated 1000 times and the observations accumulated in the sample variable .CW s. The function .CW s.stat() returns a tuple containing count, mean, minimum, maximum and standard deviation for the accumulated values. We assign the minimum value to our variable .CW base. The function .CW treset() arranges for the timestamp code to start returning small values and so reduces the likelihood of overflow or signing related issues. .LP The last section of code outputs one line containing the individual observations separated by spaces and with a suitably formatted initial \fIword\fR which labels the line so that .CW plot can make a useful interpretation of the results. .KS .LP The functions .CW treset() and .CW tstamp() make use of files served by \fIdevbench\fR and look like this: .P1 tsfd: ref Sys->FD; treset() { tsfd = sys->open("/dev/busec", sys->OWRITE); if(tsfd == nil) return; buf := array[1] of byte; n := sys->write(tsfd, buf, len buf); tsfd = sys->open("/dev/busec", sys->OREAD); } .P3 tstamp(): big { buf := array[128] of byte; n := sys->read(tsfd, buf, len buf); if(n < 0) return big 0; return big string buf[0:n]; } .P2 .KE \fIDevbench\fR must have been previously bound into the namespace .P1 bind -b '#x' /dev .P2 so that the files .P1 /dev/bctl /dev/bdata /dev/busec .P2 are available. A microsecond timestamp is provided by reading from .CW /dev/busec and is reset to zero each time anthing is written to it. The function .CW treset() resets the timestamp by writing to the file and then opens it for reading. The function .CW tstamp() reads the timestamp from the file and converts it into a .CW big value for use in the program. The device driver ignores the offset when reading from the file so that it is not necessary to .CW seek to the beginning of the file before each read. The important part of the benchmark consists of two consecutive calls to .CW tstamp(). We need to identify where time is being spent; either in the calls to .CW tstamp() or else inside the function itself. .SH Costing .LP The \fIdevbench\fR suite of programs includes one for timing individual lines of Limbo code and breaking down the time spent on each line into times for each of the Dis operations invoked by that line; the program is called \fIcost\fR. To find out how long each part of the benchmark timing loop takes we can invoke .P1 cost -f bench.b -s bench .P2 Which results in the following output - edited to just show the timing loop and the function .CW tstamp() \&. The first line is the output from \fIbench\fR giving the mean, minimum, maximum and standard deviation of microsecond times for 1000 repetitions of the loop. We see a minimum of 402 microseconds and a maximum of just over 9 milliseconds. The remaining lines are the output of \fIcost\fR; those beginning with a dash are Dis operation times for the preceding Limbo source code line. Dis operation lines contain an operation name, an execution count and the mean, minimum, maximum and standard deviation of execution times. .P1 BASE:summary:Sample:n:Time:us 1000 486 402 9053 499 -- bench.b \&... treset(); - frame 1 2.13 us 2.13 us 2.13 us 0 ns - call 1 807 ns 807 ns 807 ns 0 ns s := Sample.new(NREP*10); - mframe 1 4.85 us 4.85 us 4.85 us 0 ns - movw 1 2.27 us 2.27 us 2.27 us 0 ns - lea 1 1.57 us 1.57 us 1.57 us 0 ns - mcall 1 2.71 us 2.71 us 2.71 us 0 ns for(i:=0; i<NREP*10; i++) { - movw 1 1.99 us 1.99 us 1.99 us 0 ns - blew 1001 1.60 us 1.51 us 34.04 us 1.03 us t0 = tstamp(); - frame 1000 2.43 us 2.29 us 3.40 us 133 ns - lea 1000 1.00 us 953 ns 27.74 us 847 ns - call 1000 1.45 us 1.29 us 2.24 us 153 ns t1 = tstamp(); - frame 1000 3.45 us 3.01 us 5.57 us 293 ns - lea 1000 1.22 us 1.02 us 1.61 us 173 ns - call 1000 1.44 us 1.29 us 1.75 us 140 ns s.add(t1-t0); - mframe 1000 3.65 us 3.37 us 24.73 us 700 ns - movp 1000 1.99 us 1.48 us 2.96 us 267 ns - subl 1000 2.43 us 2.23 us 4.80 us 173 ns - mcall 1000 2.11 us 1.95 us 2.51 us 120 ns - addw 1000 1.62 us 1.48 us 2.50 us 127 ns - jmp 1000 1.50 us 1.37 us 1.81 us 120 ns } (nil, nil, base, nil, nil) = s.stat(); - mframe 1 2.66 us 2.66 us 2.66 us 0 ns - movp 1 1.39 us 1.39 us 1.39 us 0 ns - lea 1 1.41 us 1.41 us 1.41 us 0 ns - mcall 1 1.37 us 1.37 us 1.37 us 0 ns - movl 1 1.56 us 1.56 us 1.56 us 0 ns if(sflag) - beqw 1 2.14 us 2.14 us 2.14 us 0 ns iob.puts("BASE:summary:Sample:n:Time:us " + s.str() + "\\n"); - mframe 1 4.01 us 4.01 us 4.01 us 0 ns - movp 1 2.87 us 2.87 us 2.87 us 0 ns - mframe 1 1.75 us 1.75 us 1.75 us 0 ns - movp 1 1.69 us 1.69 us 1.69 us 0 ns - lea 1 1.15 us 1.15 us 1.15 us 0 ns - mcall 1 2.35 us 2.35 us 2.35 us 0 ns - addc 1 19.57 us 19.57 us 19.57 us 0 ns - addc 1 8.55 us 8.55 us 8.55 us 0 ns - lea 1 1.49 us 1.49 us 1.49 us 0 ns - mcall 1 3.65 us 3.65 us 3.65 us 0 ns iob.flush(); - mframe 1 4.50 us 4.50 us 4.50 us 0 ns - movp 1 2.13 us 2.13 us 2.13 us 0 ns - lea 1 967 ns 967 ns 967 ns 0 ns - mcall 1 1.89 us 1.89 us 1.89 us 0 ns } \&... .P3 # return timestamp in microseconds tstamp(): big { buf := array[128] of byte; - newa 2000 6.98 us 5.37 us 80.91 us 2.43 us n := sys->read(tsfd, buf, len buf); - mframe 2000 3.05 us 2.59 us 4.05 us 227 ns - movp 2000 2.33 us 2.14 us 3.21 us 120 ns - movp 2000 1.19 us 1.14 us 2.93 us 73 ns - lena 2000 1.07 us 907 ns 34.48 us 760 ns - lea 2000 893 ns 860 ns 33.00 us 907 ns - mcall 2000 133.81 us 89.88 us 8.61 ms 514.44 us if(n < 0) - blew 2000 2.27 us 1.76 us 3.43 us 313 ns return big 0; return big string buf[0:n]; - movp 2000 2.21 us 1.67 us 3.38 us 253 ns - slicea 2000 10.06 us 8.35 us 39.31 us 1.40 us - cvtac 2000 12.02 us 11.13 us 16.63 us 553 ns - cvtcl 2000 16.39 us 15.78 us 45.16 us 787 ns - ret 2000 10.52 us 9.79 us 13.97 us 333 ns } .P2 We can see from these figures that times for both calls to .CW tstamp() are reasonably low. But looking at the call to .CW "sys->read()" in .CW tstamp() we can see a maximum of just over 8½ milliseconds for the \fImcall\fR operation. We see too that this operation also has a high standard deviation of 514 microseconds across 2000 calls and so it looks like it may be the cause of the large observed delays. .LP In order to get a second view of what was happening we surrounded the timing code with calls to enable kernel profiling. .P1 profon(); for(i:=0; i<NREP*10; i++) { t0 = tstamp(); t1 = tstamp(); s.add(t1-t0); } profoff(); \&... profon() { if(sys->write(kpctl, array of byte "startclr", 8) < 8) error("kprof start"); } profoff() { if(sys->write(kpctl, array of byte "stop", 4) < 4) error("kprof stop"); } .P2 Having previously bound in \fIdevkprof\fR .P1 bind -b '#T' /dev .P2 and opened \fI/dev/kpctl\fR for writing. By examining the contents of \fI/dev/kpdata\fR with \fIkprof\fR we see that the garbage collection functions \fImarkheap\fR and \fIrungc\fR are taking up a surprisingly large amount of kernel time for this operation. .P1 total: 1460 in kernel text: 1460 outside kernel text: 0 KTZERO 80100000 ms % sym 130 8.9 markheap 110 7.5 iunlock 100 6.8 xec 90 6.1 rungc 80 5.4 chartorune 70 4.7 c2string 60 4.1 numbconv 50 3.4 string2c 40 2.7 sched 40 2.7 wakeup 30 2.0 splhi 30 2.0 freeptrs 30 2.0 memset 30 2.0 dodiv 30 2.0 _divvu 30 2.0 strtoll 20 1.3 _mulv 20 1.3 vmachine 20 1.3 unlock 20 1.3 runproc 20 1.3 DEA 10 0.6 kwrite