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}