1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
|
=head1 NAME
MT::Util::ReqTimer
=head1 DESCRIPTION
This is a simple class to let us get custom and granular
and log parts of the request cycle.
Note that the timerlogger has got some custom stuff in
it to handle the data we're passing into it, so that
it can log pretty in some placess and machine-readable
in other places.
Requires installation of Time::HiRes and List::Util
(Time::HiRes is core to Perl 5.8.0 and later).
=cut
package MT::Util::ReqTimer;
use strict;
use List::Util qw( sum );
use Time::HiRes;
our $Timer;
sub instance {
return $Timer ||= shift->new;
}
sub new {
my $class = shift;
$class = ref $class || $class;
my $self = bless {}, $class;
$self->start( @_ );
return $self;
}
sub start {
my $self = shift;
$self->{uri} = shift || '';
$self->{prev} = $self->{first} = Time::HiRes::time();
$self->{paused} = [];
$self->{elapsed} = 0;
$self->{dur} = [];
}
sub mark {
my ($self, $mark_str) = @_;
$mark_str = (caller(1))[3] unless $mark_str;
my $now = Time::HiRes::time();
my $dur = $now - $self->{prev};
$self->{elapsed} += $dur;
push @{$self->{dur}}, [ $dur, $mark_str, $self->{elapsed} ];
if (@{$self->{paused}}) {
my $paused = pop @{$self->{paused}};
if (ref $paused ne 'ARRAY') {
$paused = [];
}
my ($start, $end) = @$paused;
#back up enough to account for the time spent doing other things
$self->{prev} = $start - ($end - $now);
} else {
$self->{prev} = $now;
}
}
sub log {
my $self = shift;
#my $timerlogger = Log::Log4perl::get_logger('TypeCore::Util::ReqTimer');
#$timerlogger->info($self->{uri}, $self->{dur});
}
sub dump_line {
my $self = shift;
my (@more) = @_;
my @lines;
push @lines, "pid=$$";
push @lines, "uri=[" . $self->{uri} . ']' if $self->{uri};
push @lines, @more if @more;
my $total = 0;
my $threshold = MT->config->PerformanceLoggingThreshold;
foreach ( @{$self->{dur}} ) {
my $dur = $_->[0];
if ($_->[1] =~ m/^total\b/) {
$dur = $_->[2];
}
if ($dur >= $threshold) {
push @lines, sprintf("%s=%.5f", $_->[1], $dur);
}
$total += $_->[0];
}
push @lines, sprintf("Total=%.5f", $total);
my @times = localtime(time);
my $mon = ('Jan','Feb','Mar','Apr','May','Jun','Jul','Aug','Sep','Oct','Nov','Dec')[$times[4]];
my $day = ('Sun','Mon','Tue','Wed','Thu','Fri','Sat')[$times[6]];
my $mday = $times[3];
my $year = $times[5]+1900;
my ($hr, $mn, $sc) = ($times[2], $times[1], $times[0]);
my $ts = sprintf("%s %s %s %02d:%02d:%02d %04d", $day, $mon, $mday, $hr, $mn, $sc, $year);
require Sys::Hostname; # available in core as of Perl 5.6.0
my $hostname = Sys::Hostname::hostname();
return "[$ts] $hostname pt-times: " . join(", ", @lines) . "\n";
}
sub dump {
my $self = shift;
my $lines = '';
my $total = 0;
my $threshold = MT->config->PerformanceLoggingThreshold;
foreach ( @{$self->{dur}} ) {
my $dur = $_->[0];
if ($_->[1] =~ m/^total\b/) {
$dur = $_->[2];
}
if ($dur >= $threshold) {
$lines .= sprintf("%s - %.5f %s\n", $$, $dur, $_->[1]);
}
$total += $_->[0];
}
$lines .= sprintf("%s - %.5f --Total-- %s\n", $$, $total, $self->{uri});
return $lines;
}
sub pause_partial {
my $self = shift;
my $now = Time::HiRes::time();
push @{$self->{paused}}, [$self->{prev}, $now];
$self->{prev} = $now;
}
sub unpause {
my ($self) = @_;
my $now = Time::HiRes::time();
my $dur = $now - $self->{prev};
$self->{elapsed} += $dur;
if (@{$self->{paused}}) {
my $paused = pop @{$self->{paused}};
if (ref $paused ne 'ARRAY') {
$paused = [];
}
my ($start, $end) = @$paused;
#back up enough to account for the time spent doing other things
$self->{prev} = $start - ($end - $now);
} else {
$self->{prev} = $now;
}
}
sub total_elapsed {
my $timer = shift;
return Time::HiRes::time() - $timer->{first};
}
1;
|
