1#!/usr/local/bin/perl -w 2use strict; 3use Time::HiRes qw(time); 4use lib qw(../lib); 5use Log::Dispatch::File; 6use Log::Dispatch::FileShared; 7 8my $count = 10000; 9my $logfile = 'test.log'; 10 11{ 12 # Preload the objects so that any required modules (if any) are loaded. 13 Log::Dispatch::File->new( 14 name => 'test', 15 min_level => 'debug', 16 filename => $logfile, 17 ); 18 #->log( 'level' => 'debug', 'message' => "Start up.\n" ); 19 Log::Dispatch::FileShared->new( 20 name => 'test', 21 min_level => 'debug', 22 filename => $logfile, 23 ); 24 #->log( 'level' => 'debug', 'message' => "Start up.\n" ); 25 unlink($logfile); 26} 27 28 29if (1) { 30 print "Measuring $count logs of using defaults...\n"; 31 { 32 sleep 1; # makes measurements more fair and accurate 33 print "\tLog::Dispatch::FileShared... "; 34 my $o = Log::Dispatch::FileShared->new( 35 name => 'test', 36 min_level => 'debug', 37 filename => $logfile, 38 ); 39 my $t0 = time(); 40 for (my $i=0; $i<$count; $i++) { 41 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 42 } 43 my $t1 = time(); 44 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 45 unlink($logfile); 46 } 47 { 48 sleep 1; # makes measurements more fair and accurate 49 print "\tLog::Dispatch::File... "; 50 my $o = Log::Dispatch::File->new( 51 name => 'test', 52 min_level => 'debug', 53 filename => $logfile, 54 ); 55 my $t0 = time(); 56 for (my $i=0; $i<$count; $i++) { 57 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 58 } 59 my $t1 = time(); 60 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 61 unlink($logfile); 62 } 63} 64 65 66 67if (1) { 68 print "Measuring $count logs of using autoflush=0, flock=0...\n"; 69 { 70 sleep 1; # makes measurements more fair and accurate 71 print "\tLog::Dispatch::FileShared... "; 72 my $o = Log::Dispatch::FileShared->new( 73 name => 'test', 74 min_level => 'debug', 75 filename => $logfile, 76 autoflush => 0, 77 'flock' => 0, 78 ); 79 my $t0 = time(); 80 for (my $i=0; $i<$count; $i++) { 81 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 82 } 83 my $t1 = time(); 84 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 85 unlink($logfile); 86 } 87 { 88 sleep 1; # makes measurements more fair and accurate 89 print "\tLog::Dispatch::File... "; 90 my $o = Log::Dispatch::File->new( 91 name => 'test', 92 min_level => 'debug', 93 filename => $logfile, 94 autoflush => 0, 95 ); 96 my $t0 = time(); 97 for (my $i=0; $i<$count; $i++) { 98 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 99 } 100 my $t1 = time(); 101 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 102 unlink($logfile); 103 } 104} 105 106 107if (1) { 108 print "Measuring $count logs of using autoflush=1, flock=0...\n"; 109 { 110 sleep 1; # makes measurements more fair and accurate 111 print "\tLog::Dispatch::FileShared... "; 112 my $o = Log::Dispatch::FileShared->new( 113 name => 'test', 114 min_level => 'debug', 115 filename => $logfile, 116 autoflush => 1, 117 'flock' => 0, 118 ); 119 my $t0 = time(); 120 for (my $i=0; $i<$count; $i++) { 121 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 122 } 123 my $t1 = time(); 124 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 125 unlink($logfile); 126 } 127 { 128 sleep 1; # makes measurements more fair and accurate 129 print "\tLog::Dispatch::File... "; 130 my $o = Log::Dispatch::File->new( 131 name => 'test', 132 min_level => 'debug', 133 filename => $logfile, 134 autoflush => 1, 135 ); 136 my $t0 = time(); 137 for (my $i=0; $i<$count; $i++) { 138 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 139 } 140 my $t1 = time(); 141 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 142 unlink($logfile); 143 } 144} 145 146 147if (1) { 148 print "Measuring $count logs of using flock=1...\n"; 149 { 150 sleep 1; # makes measurements more fair and accurate 151 print "\tLog::Dispatch::FileShared... "; 152 my $o = Log::Dispatch::FileShared->new( 153 name => 'test', 154 min_level => 'debug', 155 filename => $logfile, 156 ); 157 my $t0 = time(); 158 for (my $i=0; $i<$count; $i++) { 159 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 160 } 161 my $t1 = time(); 162 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 163 unlink($logfile); 164 } 165 { 166 sleep 1; # makes measurements more fair and accurate 167 print "\tLog::Dispatch::File... "; 168 my $o = Log::Dispatch::File->new( 169 name => 'test', 170 min_level => 'debug', 171 filename => $logfile, 172 ); 173 my $t0 = time(); 174 for (my $i=0; $i<$count; $i++) { 175 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 176 } 177 my $t1 = time(); 178 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 179 unlink($logfile); 180 } 181} 182 183 184if (1) { 185 print "Measuring $count logs of using close_after_write=1, flock=0...\n"; 186 { 187 sleep 1; # makes measurements more fair and accurate 188 print "\tLog::Dispatch::FileShared... "; 189 my $o = Log::Dispatch::FileShared->new( 190 name => 'test', 191 min_level => 'debug', 192 filename => $logfile, 193 close_after_write => 1, 194 'flock' => 0, 195 ); 196 my $t0 = time(); 197 for (my $i=0; $i<$count; $i++) { 198 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 199 } 200 my $t1 = time(); 201 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 202 unlink($logfile); 203 } 204 { 205 sleep 1; # makes measurements more fair and accurate 206 print "\tLog::Dispatch::File... "; 207 my $o = Log::Dispatch::File->new( 208 name => 'test', 209 min_level => 'debug', 210 filename => $logfile, 211 close_after_write => 1, 212 ); 213 my $t0 = time(); 214 for (my $i=0; $i<$count; $i++) { 215 $o->log( 'level' => 'debug', 'message' => "This is a debug message.\n" ); 216 } 217 my $t1 = time(); 218 printf("%.3f seconds\t(avg %.5f)\n", $t1 - $t0, ($t1 - $t0) / $count); 219 unlink($logfile); 220 } 221}