parse_logs 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357
  1. #!/usr/bin/perl
  2. # Parse the log output files of run-experiment
  3. # Send concatenated log files to stdin, or list them on the command
  4. # line.
  5. use strict;
  6. my $mode = '';
  7. my $depth = 0;
  8. my $numops = 0;
  9. my $phase = '';
  10. my $numparties = '';
  11. my $what = '';
  12. my $setupsize = 0;
  13. my $opsize = 0;
  14. my @seconds = (0, 0);
  15. my $netsetup = '';
  16. my %preproc_s_data = ();
  17. my %preproc_kib_data = ();
  18. my %online_s_data = ();
  19. my %online_kib_data = ();
  20. while(<>) {
  21. chomp;
  22. if (/Network setup: (.*)/) {
  23. $netsetup = "$1 ";
  24. next;
  25. }
  26. if (/===== Running duoram (\S+) (\d+) (\d+) (\S+) ([23]P)/) {
  27. $mode = $1;
  28. $depth = $2;
  29. $numops = $3;
  30. $phase = $4;
  31. $numparties = $5;
  32. my $label = "${numparties}Duoram $mode $depth $netsetup$numops";
  33. if ($mode eq "read" && $numparties eq "2P") {
  34. &parse_2P_read($label);
  35. } elsif ($mode eq "write" && $numparties eq "2P" && $phase eq "preproc") {
  36. &parse_2P_write_preproc($label);
  37. } elsif ($mode eq "write" && $numparties eq "2P" && $phase eq "online") {
  38. &parse_2P_write_online($label);
  39. } elsif ($numparties eq "3P" && $phase eq "preproc") {
  40. &parse_3P_preproc("$depth $netsetup$numops");
  41. } elsif ($numparties eq "3P" && $phase eq "online") {
  42. &parse_3P_online("$depth $netsetup$numops");
  43. }
  44. @seconds = (0,0);
  45. $what = '';
  46. $setupsize = 0;
  47. $opsize = 0;
  48. next;
  49. }
  50. }
  51. # Convert the data (in the form [n, sum, sum_squares]) to statistics (in
  52. # the form [mean, variance])
  53. my %preproc_s_stats = ();
  54. my %preproc_kib_stats = ();
  55. my %online_s_stats = ();
  56. my %online_kib_stats = ();
  57. &statsify(\%preproc_s_stats, \%preproc_s_data);
  58. &statsify(\%preproc_kib_stats, \%preproc_kib_data);
  59. &statsify(\%online_s_stats, \%online_s_data);
  60. &statsify(\%online_kib_stats, \%online_kib_data);
  61. # The 2P readwrite values are just the sums of the read and the write values
  62. &sum_readwrite_2P(\%preproc_s_stats);
  63. &sum_readwrite_2P(\%preproc_kib_stats);
  64. &sum_readwrite_2P(\%online_s_stats);
  65. &sum_readwrite_2P(\%online_kib_stats);
  66. # The total values are the sums of the preproc and online values
  67. my %total_s_stats = ();
  68. my %total_kib_stats = ();
  69. &sum_preproc_online(\%total_s_stats, \%preproc_s_stats, \%online_s_stats);
  70. &sum_preproc_online(\%total_kib_stats, \%preproc_kib_stats, \%online_kib_stats);
  71. # Output the data
  72. &output_stats(\%preproc_s_stats, "Preprc", "s");
  73. &output_stats(\%preproc_kib_stats, "Preprc", "KiB");
  74. &output_stats(\%online_s_stats, "Onln", "s");
  75. &output_stats(\%online_kib_stats, "Onln", "KiB");
  76. &output_stats(\%total_s_stats, "Totl", "s");
  77. &output_stats(\%total_kib_stats, "Totl", "KiB");
  78. # Subroutines
  79. sub parse_2P_read {
  80. my $label = $_[0];
  81. my $who = 0;
  82. my @preproc_s = ();
  83. my @preproc_kib = ();
  84. my @online_s = ();
  85. my @online_kib = ();
  86. while(<>) {
  87. last if /===== End/;
  88. if (/===== P([012]) output/) {
  89. $who = $1;
  90. next;
  91. }
  92. if (/Total preprocessing time: (\d+) µs/) {
  93. $preproc_s[$who] = $1 / 1000000;
  94. }
  95. if (/Total preprocessing bytes: (\d+)/) {
  96. $preproc_kib[$who] = $1 / 1024;
  97. }
  98. if (/Total query time: (\d+) µs/) {
  99. $online_s[$who] = $1 / 1000000;
  100. }
  101. if (/Total query bytes: (\d+)/) {
  102. $online_kib[$who] = $1 / 1024;
  103. }
  104. }
  105. return if $#preproc_s < 0;
  106. &accum_data(\%preproc_s_data, $label, &maxarray(@preproc_s));
  107. &accum_data(\%preproc_kib_data, $label, &avgarray(@preproc_kib));
  108. &accum_data(\%online_s_data, $label, &maxarray(@online_s));
  109. &accum_data(\%online_kib_data, $label, &avgarray(@online_kib));
  110. }
  111. sub parse_2P_write_preproc {
  112. my $label = $_[0];
  113. my $who = 0;
  114. my @preproc_s = ();
  115. my @preproc_kib = ();
  116. while(<>) {
  117. last if /===== End/;
  118. if (/===== P([012]) output/) {
  119. $who = $1;
  120. next;
  121. }
  122. if (/time to generate and evaluate \d+ OTs is: (\d+\.?\d*+)s/) {
  123. $preproc_s[$who] = $1;
  124. }
  125. if (/bytes transmitted for OT = (\d+) bytes/) {
  126. $preproc_kib[$who] = $1 / 1024;
  127. }
  128. if (/WallClockTime: (\d+\.?\d*) s/) {
  129. $preproc_s[$who] += $1;
  130. }
  131. if (/CommunicationCost: (\d+) bytes/) {
  132. $preproc_kib[$who] += $1 / 1024;
  133. }
  134. }
  135. return if $#preproc_s < 0;
  136. &accum_data(\%preproc_s_data, $label, &maxarray(@preproc_s));
  137. &accum_data(\%preproc_kib_data, $label, &avgarray(@preproc_kib));
  138. }
  139. sub parse_2P_write_online {
  140. my $label = $_[0];
  141. my $who = 0;
  142. my @online_s = ();
  143. my @online_kib = ();
  144. while(<>) {
  145. last if /===== End/;
  146. if (/===== P([012]) output/) {
  147. $who = $1;
  148. next;
  149. }
  150. if (/write_time = (\d+\.?\d*)/) {
  151. $online_s[$who] = $1;
  152. }
  153. if (/communication_cost_writes = (\d+) bytes/) {
  154. $online_kib[$who] = $1 / 1024;
  155. }
  156. }
  157. return if $#online_s < 0;
  158. &accum_data(\%online_s_data, $label, &maxarray(@online_s));
  159. &accum_data(\%online_kib_data, $label, &avgarray(@online_kib));
  160. }
  161. sub parse_3P_preproc {
  162. my $labelsuffix = $_[0];
  163. my $who = 0;
  164. my @preproc_s = ();
  165. my @preproc_kib = ();
  166. while(<>) {
  167. last if /===== End/;
  168. if (/WallClockTime: (\d+\.?\d*)/) {
  169. $preproc_s[$who] = $1;
  170. }
  171. if (/CommunicationCost: (\d+) bytes/) {
  172. $preproc_kib[$who] = $1 / 1024;
  173. }
  174. }
  175. return if $#preproc_s < 0;
  176. &accum_data(\%preproc_s_data, "3PDuoram read $labelsuffix", &maxarray(@preproc_s));
  177. &accum_data(\%preproc_kib_data, "3PDuoram read $labelsuffix", &avgarray(@preproc_kib));
  178. &accum_data(\%preproc_s_data, "3PDuoram write $labelsuffix", &maxarray(@preproc_s));
  179. &accum_data(\%preproc_kib_data, "3PDuoram write $labelsuffix", &avgarray(@preproc_kib));
  180. &accum_data(\%preproc_s_data, "3PDuoram readwrite $labelsuffix", 2*&maxarray(@preproc_s));
  181. &accum_data(\%preproc_kib_data, "3PDuoram readwrite $labelsuffix", 2*&avgarray(@preproc_kib));
  182. }
  183. sub parse_3P_online {
  184. my $labelsuffix = $_[0];
  185. my $who = 0;
  186. my @read_s = ();
  187. my @read_kib = ();
  188. my @write_s = ();
  189. my @write_kib = ();
  190. my @readwrite_s = ();
  191. my @readwrite_kib = ();
  192. while(<>) {
  193. last if /===== End/;
  194. if (/===== P([012]) output/) {
  195. $who = $1;
  196. next;
  197. }
  198. if (/write_time =\s+(\d+\.?\d*)/) {
  199. $write_s[$who] = $1;
  200. }
  201. if (/communication_cost_writes = (\d+) bytes/) {
  202. $write_kib[$who] = $1 / 1024;
  203. }
  204. if (/dependent_read_time =\s+(\d+\.?\d*)/) {
  205. $read_s[$who] = $1;
  206. }
  207. if (/communication_cost_dep_read = (\d+) bytes/) {
  208. $read_kib[$who] = $1 / 1024;
  209. }
  210. if (/interleaved_time =\s+(\d+\.?\d*)/) {
  211. $readwrite_s[$who] = $1;
  212. }
  213. if (/communication_cost_interleaved = (\d+) bytes/) {
  214. $readwrite_kib[$who] = $1 / 1024;
  215. }
  216. }
  217. return if $#read_s < 0;
  218. &accum_data(\%online_s_data, "3PDuoram read $labelsuffix", &maxarray(@read_s));
  219. &accum_data(\%online_kib_data, "3PDuoram read $labelsuffix", &avgarray(@read_kib));
  220. &accum_data(\%online_s_data, "3PDuoram write $labelsuffix", &maxarray(@write_s));
  221. &accum_data(\%online_kib_data, "3PDuoram write $labelsuffix", &avgarray(@write_kib));
  222. &accum_data(\%online_s_data, "3PDuoram readwrite $labelsuffix", &maxarray(@readwrite_s));
  223. &accum_data(\%online_kib_data, "3PDuoram readwrite $labelsuffix", &avgarray(@readwrite_kib));
  224. }
  225. sub maxarray {
  226. my $max = $_[0];
  227. foreach (@_) {
  228. $max = $_ if $_ > $max;
  229. }
  230. $max;
  231. }
  232. sub avgarray {
  233. my $sum = 0;
  234. my $n = 0;
  235. foreach (@_) {
  236. $sum += $_;
  237. $n += 1;
  238. }
  239. $sum / $n;
  240. }
  241. # Pass:
  242. # - a reference to a dictionary
  243. # - the key into that dictionary
  244. # - the new data point
  245. # Data is stored in the dictionary as a triple (n, sum, sum_squares)
  246. sub accum_data {
  247. my ($dict, $key, $data) = @_;
  248. $dict->{$key} = [0, 0, 0] unless defined $dict->{$key};
  249. $dict->{$key}->[0] += 1;
  250. $dict->{$key}->[1] += $data;
  251. $dict->{$key}->[2] += ($data * $data);
  252. }
  253. # Convert data (in the form [n, sum, sum_squares]) to statistics (in
  254. # the form [mean, variance])
  255. sub statsify {
  256. my ($sdict, $ddict) = @_;
  257. my $key;
  258. foreach $key (keys %$ddict) {
  259. my $data = $ddict->{$key};
  260. my $n = $data->[0];
  261. my $sum = $data->[1];
  262. my $sumsq = $data->[2];
  263. if ($n == 0) {
  264. $sdict->{$key} = [undef, undef];
  265. } elsif ($n == 1) {
  266. $sdict->{$key} = [$sum, undef];
  267. } else {
  268. $sdict->{$key} = [$sum/$n, ($sumsq - ($sum*$sum/$n))/($n-1)];
  269. }
  270. }
  271. }
  272. # Turn a stat array [mean, variance] into a string to display
  273. sub statstr {
  274. my $data = $_[0];
  275. if (defined $data->[1]) {
  276. my $mean = $data->[0];
  277. my $stddev = sqrt($data->[1]);
  278. return "$mean ± $stddev";
  279. } elsif (defined $data->[0]) {
  280. return $data->[0];
  281. } else {
  282. return "none"
  283. }
  284. }
  285. # Sum two stat arrays
  286. sub statsum {
  287. my ($data0, $data1) = @_;
  288. if (defined $data0->[1] && defined $data1->[1]) {
  289. return [$data0->[0] + $data1->[0], $data0->[1] + $data1->[1]];
  290. } else {
  291. return [$data0->[0] + $data1->[0], undef];
  292. }
  293. }
  294. # The 2P readwrite values are just the sums of the read and the write values
  295. sub sum_readwrite_2P {
  296. my $dict = $_[0];
  297. my $key;
  298. foreach $key (keys %$dict) {
  299. if ($key =~ /^2PDuoram read /) {
  300. my $writekey = $key;
  301. my $readwritekey = $key;
  302. $writekey =~ s/^2PDuoram read /2PDuoram write /;
  303. $readwritekey =~ s/^2PDuoram read /2PDuoram readwrite /;
  304. if (defined $dict->{$writekey}) {
  305. $dict->{$readwritekey} = &statsum($dict->{$key}, $dict->{$writekey});
  306. } else {
  307. # It's OK if we're missing the data point, since we
  308. # don't necessary parse all the data at once.
  309. # print "Missing data point for $writekey\n";
  310. }
  311. }
  312. }
  313. }
  314. # Add the preproc and online stats to get the total stats
  315. sub sum_preproc_online {
  316. my ($tdict, $pdict, $odict) = @_;
  317. my $key;
  318. foreach $key (keys %$pdict) {
  319. if (defined $odict->{$key}) {
  320. $tdict->{$key} = &statsum($pdict->{$key}, $odict->{$key});
  321. }
  322. }
  323. }
  324. # Output the stats in the given dictionary. Append $phase to the
  325. # protocol name, and add $units to the end.
  326. sub output_stats {
  327. my ($dict, $phase, $units) = @_;
  328. my $label;
  329. foreach $label (sort keys %$dict) {
  330. my $printlabel = $label;
  331. $printlabel =~ s/PDuoram/PDuoram$phase/;
  332. print $printlabel, " ", &statstr($dict->{$label}), " $units\n";
  333. }
  334. }