1 /** avgtime - Runs a command with an optional repetition and shows
2  *  statistics of the time it took.
3  *
4  * License:   <a href="http://www.boost.org/LICENSE_1_0.txt">Boost License 1.0</a>.
5  * Authors:   Juan Manuel Cabo
6  * Version:   0.6
7  * Source:    avgtime.d
8  * Last update: 2015-04-30
9  */
10 /*          Copyright Juan Manuel Cabo 2012-2015.
11  * Distributed under the Boost Software License, Version 1.0.
12  *    (See accompanying file LICENSE_1_0.txt or copy at
13  *          http://www.boost.org/LICENSE_1_0.txt)
14  */
15 
16 module avgtime;
17 
18 import std.stdio, std.process, std.getopt, core.time, std..string, std.conv;
19 import std.algorithm, std.array, std.math;
20 
21 
22 //Uncomment to use spanProcess() instead of fork() and CreateProcess().
23 //
24 //The SpawnProcess version is cleaner and portable across Linux, OSX and
25 //Windows, but it has some slight overhead which is measurable (sadly). 
26 //The other versions are faster and cover the three OSs.
27 //  The slight overhead can be measured when running quick programs (like "void main() { }")
28 //it might be so small that it can be ignored it if the measured program takes long to run,
29 //but I cannot leave SpawnProcess as default.
30 //
31 // version = SpawnProcess;
32 
33 version(SpawnProcess) {
34 } else version(Posix) {
35     import core.sys.posix.unistd;
36     import core.sys.posix.sys.wait;
37 } else version(Windows) {
38     import core.sys.windows.windows;
39 
40     extern(Windows) {
41         struct STARTUPINFOA {
42             DWORD cb;
43             LPSTR lpReserved;
44             LPSTR lpDesktop;
45             LPSTR lpTitle;
46             DWORD dwX;
47             DWORD dwY;
48             DWORD dwXSize;
49             DWORD dwYSize;
50             DWORD dwXCountChars;
51             DWORD dwYCountChars;
52             DWORD dwFillAttribute;
53             DWORD dwFlags;
54             WORD wShowWindow;
55             WORD cbReserved2;
56             LPBYTE lpReserved2;
57             HANDLE hStdInput;
58             HANDLE hStdOutput;
59             HANDLE hStdError;
60         }
61         alias STARTUPINFOA* LPSTARTUPINFOA;
62 
63         immutable DWORD STARTF_USESTDHANDLES = 0x00000100;
64 
65         /*
66         struct SECURITY_ATTRIBUTES {
67             DWORD nLength;
68             LPVOID lpSecurityDescriptor;
69             BOOL bInheritHandle;
70         }
71         alias SECURITY_ATTRIBUTES* PSECURITY_ATTRIBUTES;
72         alias SECURITY_ATTRIBUTES* LPSECURITY_ATTRIBUTES;
73         */
74 
75         struct PROCESS_INFORMATION {
76             HANDLE hProcess;
77             HANDLE hThread;
78             DWORD dwProcessId;
79             DWORD dwThreadId;
80         }
81         alias PROCESS_INFORMATION* PPROCESS_INFORMATION;
82         alias PROCESS_INFORMATION* LPPROCESS_INFORMATION;
83 
84         export BOOL CreateProcessA(LPCSTR lpApplicationName,
85             LPSTR lpCommandLine,
86             LPSECURITY_ATTRIBUTES lpProcessAttributes,
87             LPSECURITY_ATTRIBUTES lpThreadAttributes,
88             BOOL bInheritHandles, DWORD dwCreationFlags, LPVOID lpEnvironment,
89             LPCSTR lpCurrentDirectory, LPSTARTUPINFOA lpStartupInfo,
90             LPPROCESS_INFORMATION lpProcessInformation
91         );
92     }
93 
94 } else {
95     static assert(false, "Untested platform");
96 }
97 
98 
99 int main(string[] args) {
100     if (args.length == 1) {
101         showUsage();
102         return 0;
103     }
104 
105     //Parse options:
106     int repetitions = 1;
107     bool discardFirst = false;
108     bool quiet = false;
109     bool printTimes = false;
110     bool printHistogram = false;
111     try {
112         getopt(args,
113             std.getopt.config.caseSensitive,
114             std.getopt.config.noPassThrough,
115             std.getopt.config.stopOnFirstNonOption,
116             "discardfirst|d", &discardFirst,
117             "printtimes|p", &printTimes,
118             "printhistogram|h", &printHistogram,
119             "repetitions|r", &repetitions,
120             "quiet|q", &quiet);
121     } catch (Exception ex) {
122         stderr.writeln(ex.msg);
123         return 1;
124     }
125 
126     if (args.length < 2) {
127         showUsage();
128         return 0;
129     }
130 
131     if (repetitions <= 1) {
132         repetitions = 1;
133     }
134     if (discardFirst) {
135         ++repetitions;
136     }
137 
138     //Run the program, collecting time info.
139     string prog = args[1];
140     string[] progArgs = args[1..$];
141     TickDuration[] durations;
142     for (int i=0; i < repetitions; ++i) {
143         TickDuration duration = run(prog, progArgs, quiet);
144         if (!discardFirst || i != 0) {
145             durations ~= duration;
146         }
147     }
148 
149     //Compute and show stats:
150     showStats(durations, printTimes, printHistogram);
151 
152     return 0;
153 }
154 
155 void showUsage() {
156     version(Posix) {
157         string examples = `
158     avgtime -q -r30      ls -lR
159     avgtime -h -q -r100  ls *`;
160     } else version(Windows) {
161         string examples = `
162     avgtime -q -r30      cmd /c dir
163     avgtime -h -q -r100  fc /?`;
164     }
165 
166     writeln(
167 `avgtime - Runs a command repeatedly and shows time statistics.
168 Usage: avgtime [OPTIONS] <command> [<arguments>]
169 
170   -r, --repetitions=N    Repeat <command> N times
171   -q, --quiet            Suppress the command's stdout and stderr
172                          piping them to /dev/null.
173   -h, --printhistogram   Print a nice histogram, grouping times by
174                          most significant digits.
175   -p, --printtimes       Print all measurements in milliseconds
176   -d, --discardfirst     Performs an extra repetition, and then discards
177                          it. It's like a warmup to prevent first
178                          run outlier.
179 
180 Examples:
181 ` ~ examples ~ `
182 
183 Notes:
184 
185     * The 'sample mode' is the most frequent rounded measurement.
186 
187     * The 'median' is the timing in the middle of the sorted list of timings.
188 
189     * If the 95% confidence interval's of the timings of two programs
190       don't overlap, then you can be confident that one is faster
191       than the other.
192       This assumes a 'normal distribution', and for the assumption
193       to work, N must be at least 30. The more repetitions, the better.
194 
195     * There is a small irreductible overhead in the order of 1ms to 10ms,
196       depending on your computer and OS, inherent to forking and
197       process loading.`
198 );
199 }
200 
201 TickDuration run(string prog, string[] progArgs, bool quiet) {
202     TickDuration start;
203     TickDuration end;
204 
205     //The SpawnProcess version is cleaner and portable across Linux, OSX and
206     //Windows, but it has some slight overhead which is measurable (sadly). 
207     //The other versions are faster and cover the three OSs.
208     version(SpawnProcess) 
209     {
210         string[] progAndArgs = [prog] ~ progArgs[1..$];
211 
212         File stdoutRedir = std.stdio.stdout;
213         File stderrRedir = std.stdio.stderr;
214         if (quiet) {
215             version(Windows) {
216                 File nullOutput = File("NUL", "w");
217             } else {
218                 File nullOutput = File("/dev/null", "w");
219             }
220             stdoutRedir = nullOutput;
221             stderrRedir = nullOutput;
222         }
223 
224         try {
225             start = TickDuration.currSystemTick();
226 
227             //Run the program:
228             auto pid = spawnProcess(progAndArgs, std.stdio.stdin, stdoutRedir, stderrRedir);
229 
230             //Wait for it to finish:
231             wait(pid);
232 
233             end = TickDuration.currSystemTick();
234 
235         } catch (std.process.ProcessException ex) {
236             end = TickDuration.currSystemTick();
237             stderr.writeln("Error: command '" ~ prog  ~ "' not found.");
238         }
239     } 
240     else version(Posix)
241     {
242         start = TickDuration.currSystemTick();
243 
244         //Using fork() and execvp(). system() and shell() would
245         //invoke '/bin/sh' first which wouldn't be so direct.
246         pid_t pid = fork();
247         if (pid == 0) {
248             if (quiet) {
249                 freopen("/dev/null", "w", stdout.getFP());
250                 freopen("/dev/null", "w", stderr.getFP());
251             }
252 
253             //Run the program:
254             auto ret = std.process.execvp(prog, progArgs);
255             if (ret == -1) {
256                 stderr.writeln("Error: command '" ~ prog  ~ "' not found.");
257                 _exit(1);
258             }
259 
260             _exit(0);
261         }
262         int status;
263         waitpid(pid, &status, 0);
264         end = TickDuration.currSystemTick();
265     }
266     else version(none)
267     {
268         progArgs = progArgs[1..$];
269         string cmdLine = prog ~ " " ~ join(progArgs, " ");
270         start = TickDuration.currSystemTick();
271         //The system() function works, but it first invokes a shell:
272         system(cmdLine);
273         end = TickDuration.currSystemTick();
274     }
275     else version(Windows)
276     {
277         progArgs = progArgs[1..$];
278         string cmdLine = prog ~ " " ~ join(progArgs, " ");
279 
280         PROCESS_INFORMATION processInfo;
281         STARTUPINFOA startupInfo;
282         startupInfo.cb = startupInfo.sizeof;
283 
284         HANDLE handleNull;
285         LPSECURITY_ATTRIBUTES saProcess = null;
286         if (quiet) {
287             startupInfo.dwFlags = STARTF_USESTDHANDLES;
288 
289             SECURITY_ATTRIBUTES sa;
290             sa.nLength = SECURITY_ATTRIBUTES.sizeof;
291             sa.bInheritHandle = true;
292             saProcess = &sa;
293 
294             //Open windows "NUL" file:
295             handleNull = CreateFileA("NUL", GENERIC_READ | GENERIC_WRITE,
296                     FILE_SHARE_READ | FILE_SHARE_WRITE, &sa, OPEN_EXISTING, 0,
297                     null);
298 
299             //Set "NUL" as stdout and stderr of the new process:
300             startupInfo.hStdInput = INVALID_HANDLE_VALUE;
301             startupInfo.hStdOutput = handleNull;
302             startupInfo.hStdError = handleNull;
303         }
304 
305         //Run the program
306         start = TickDuration.currSystemTick();
307         auto result = CreateProcessA(null, cast(char*)toStringz(cmdLine),
308             saProcess, saProcess, quiet, 0, null, null,
309             &startupInfo, &processInfo);
310 
311         if(!result) {
312             stderr.writeln("Error: command '" ~ prog  ~ "' not found.");
313             return TickDuration(0);
314         }
315 
316         //Wait until it finishes
317         WaitForSingleObject(processInfo.hProcess, INFINITE);
318 
319         end = TickDuration.currSystemTick();
320 
321         CloseHandle(processInfo.hProcess);
322         CloseHandle(processInfo.hThread);
323         if (quiet) {
324             CloseHandle(handleNull);
325         }
326     }
327     return end - start;
328 }
329 
330 
331 void showStats(TickDuration[] durations, bool printTimes, bool printHistogram) {
332     long N = durations.length;
333 
334     if (N == 0) {
335         writeln("Error, no time info.");
336         return;
337     }
338     if (N == 1) {
339         writeln("\n------------------------");
340         writeln("Total time (ms): ", durations[0].usecs() / 1000.0);
341         return;
342     }
343 
344     //Get sum, average and stdDev:
345     real sum = 0;
346     real sumSq = 0;
347     real min = durations[0].usecs();
348     real max = durations[0].usecs();
349     real[] durationsUsecs;
350     foreach (TickDuration duration; durations) {
351         real usecs = duration.usecs();
352         sum += usecs;
353         sumSq += usecs * usecs;
354         durationsUsecs ~= usecs;
355         if (min > usecs) { min = usecs; }
356         if (max < usecs) { max = usecs; }
357     }
358     real avg = sum / N;
359     real stdDevFast = sqrt(sumSq/N - avg * avg);
360 
361     //Sort and get median:
362     sort(durationsUsecs);
363     real median = 0;
364     if ((durationsUsecs.length % 2) == 0) {
365         //Average between the two central values
366         median = (durationsUsecs[($/2) - 1] + durationsUsecs[$/2]) / 2.0;
367     } else {
368         //Value in the middle:
369         median = durationsUsecs[$/2];
370     }
371 
372 
373     //To build a histogram and get the mode, we need to group
374     //many values into a few bins. So we'll zero out the least
375     //significant digits. Spliting into X subintervals isn't as
376     //nice as this.
377     int roundingQuotient;
378     if (min > 100_000) {
379         //Round 1234.5 to 1230.0 milliseconds.
380         roundingQuotient = 10_000;
381     } else if (min > 10_000) {
382         //Round 123.45 to 123.00 milliseconds.
383         roundingQuotient = 1000;
384     } else {
385         //Round 12.345 to 12.300 milliseconds.
386         roundingQuotient = 100;
387     }
388 
389     //Build frequencies and find sample mode at the same time:
390     int[int] frequencies;
391     real mode;
392     int maxFreq = 0;
393     foreach (real usecs; durationsUsecs) {
394         int roundedTime = cast(int)(usecs / roundingQuotient);
395         int freq = frequencies.get(roundedTime, 0);
396         ++freq;
397         frequencies[roundedTime] = freq;
398         //Get the biggest of the modes, if there is more than one:
399         if (freq >= maxFreq) {
400             maxFreq = freq;
401             mode = roundedTime * roundingQuotient / 1000.0;
402         }
403     }
404 
405     //Confidence intervals assuming a normal (gaussian) distribution:
406     immutable real z0_005 = 2.57582930355;
407     immutable real z0_025 = 1.95996398454;
408     real muError99 = z0_005 * stdDevFast / sqrt(cast(real)N);
409     real muError95 = z0_025 * stdDevFast / sqrt(cast(real)N);
410     real error99 = z0_005 * stdDevFast;
411     real error95 = z0_025 * stdDevFast;
412 
413     writeln("\n------------------------");
414     writeln("Total time (ms): ", sum / 1000.0);
415     writeln("Repetitions    : ", N);
416     writeln("Sample mode    : ", mode, " (", maxFreq, " occurrences)");
417     writeln("Median time    : ", median / 1000.0);
418     writeln("Avg time       : ", avg / 1000.0);
419     writeln("Std dev.       : ", stdDevFast / 1000.0);
420     writeln("Minimum        : ", min / 1000.0);
421     writeln("Maximum        : ", max / 1000.0);
422     writeln("95% conf.int.  : [", (avg - error95) / 1000.0, ", ",
423         (avg + error95) / 1000.0, "]  e = ", error95 / 1000.0);
424     writeln("99% conf.int.  : [", (avg - error99) / 1000.0, ", ",
425         (avg + error99) / 1000.0, "]  e = ", error99 / 1000.0);
426     writeln("EstimatedAvg95%: [", (avg - muError95) / 1000.0, ", ",
427         (avg + muError95) / 1000.0, "]  e = ", muError95 / 1000.0);
428     writeln("EstimatedAvg99%: [", (avg - muError99) / 1000.0, ", ",
429         (avg + muError99) / 1000.0, "]  e = ", muError99 / 1000.0);
430 
431 
432     //Print histogram:
433     if (printHistogram) {
434         //Normalize histogram.
435         //maxFreq is 100% (1.0), everything else is proportional.
436         float[int] histogram;
437         foreach (k,v; frequencies) {
438             histogram[k] = v / cast(float)maxFreq;
439         }
440 
441         //Sort the bins to print them in order:
442         int[] histogramKeys = array(frequencies.keys());
443         sort(histogramKeys);
444 
445         //Fix the number of digits to print after the decimal point:
446         int precision = 3 - cast(int) log10(roundingQuotient);
447         precision = std.algorithm.max(0, precision);
448         string timeFormatStr = "%5." ~ to!string(precision) ~ "f";
449 
450         writeln("Histogram      :");
451         writeln("    msecs: count  normalized bar");
452         foreach(int roundedTime; histogramKeys) {
453             //"Un-round" to get the milliseconds:
454             real msecs = roundedTime * roundingQuotient / 1000.0;
455             string msecsStr = format(timeFormatStr, msecs);
456 
457             //Bar proportional to the frequency:
458             immutable LONGEST_BAR_CHARS = 40;
459             string bars = replicate("#",
460                     cast(size_t)(histogram[roundedTime] * LONGEST_BAR_CHARS));
461 
462             writefln("    %s: %5.d  %s", msecsStr,
463                     frequencies[roundedTime], bars);
464         }
465     }
466 
467     //Print all measurements, sorted:
468     if (printTimes) {
469         string allTimes = format("%s", array(map!("a / 1000.0")(durationsUsecs)));
470         allTimes = wrap(replace(allTimes, ",", ", "), 80, "", "    ");
471 
472         string breakLineIfWrapped = (allTimes.indexOf('\n'))? "\n    " : "";
473         writeln("Sorted times   : ", breakLineIfWrapped, allTimes);
474     }
475 }
476 
477 
478