Skip to content

Commit

Permalink
Profiling
Browse files Browse the repository at this point in the history
  • Loading branch information
Dmitry Ovsyanko committed Oct 21, 2010
1 parent 20d0708 commit 00900c3
Show file tree
Hide file tree
Showing 10 changed files with 401 additions and 325 deletions.
28 changes: 1 addition & 27 deletions Eludia/Content.pm
View file
Expand Up @@ -9,6 +9,7 @@ use Eludia::Content::HTTP;
use Eludia::Content::Validators;
use Eludia::Content::Templates;
use Eludia::Content::Tie;
use Eludia::Content::Profiling;

#############################################################################

Expand Down Expand Up @@ -175,33 +176,6 @@ sub add_totals {

################################################################################

sub __log_profilinig {

my $now = time ();

my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = localtime ($now);
$year += 1900;
$mon ++;

printf STDERR "[%04d-%02d-%02d %02d:%02d:%02d:%03d $$] %7.2f ms %s\n",
$year,
$mon,
$mday,
$hour,
$min,
$sec,
int (1000 * ($now - int $now)),
1000 * ($now - $_[0]),
$_[1]

if $preconf -> {core_debug_profiling} > 0 && !$ENV {ELUDIA_SILENT};

return $now;

}

################################################################################

sub get_ids {

my ($name) = @_;
Expand Down
10 changes: 6 additions & 4 deletions Eludia/Content/Auth.pm
View file
Expand Up @@ -73,17 +73,19 @@ sub get_user_with_fixed_session {

$_REQUEST {sid} or return undef;

my $time = time ();
# __profile_in ('auth.get_user');

unless ($_REQUEST {__suggest}) {

# __profile_in ('auth.refresh_sessions');

sql_do_refresh_sessions ();

$time = __log_profilinig ($time, ' <refresh_sessions>');
# __profile_out ('auth.refresh_sessions');

}

my $st = ($SQL_VERSION -> {_} -> {st_select_user} ||= $db -> prepare_cached (get_user_sql (), {}, 3));
my $st = ($SQL_VERSION -> {_} -> {st_select_user} ||= $db -> prepare_cached (get_user_sql (), {}, 3));

$st -> execute ($_REQUEST {sid});

Expand All @@ -93,7 +95,7 @@ sub get_user_with_fixed_session {

lc_hashref ($user);

__log_profilinig ($time, ' <get_user>');
# __profile_out ('auth.get_user', {label => "$user->{id} ($user->{label})"});

$user -> {id} or return undef;

Expand Down
171 changes: 87 additions & 84 deletions Eludia/Content/Handler.pm
View file
Expand Up @@ -4,38 +4,65 @@ no warnings;

sub handler {

my $time = time ();

our $i18n = i18n ();
our @_PROFILING_STACK = ();

return _ok () if eval { page_is_not_needed (\$time, @_) };
__profile_in ('handler.request');

my $code;

eval {

my $code = $@ ? 500 : eval {
my $page_is_not_needed = eval { page_is_not_needed (@_) };

return _ok () if $page_is_not_needed;

my $page = setup_page ( ); $time = __log_profilinig ($time, '<setup_page>');
$code = $@ ? 500 : eval {

return &{"handle_request_of_type_$page->{request_type}"} ($page);
__profile_in ('handler.setup_page');

};

if ($@) {
my $page = setup_page ();
my $callee = "handle_request_of_type_$page->{request_type}";

warn "$@\n";
__profile_out ('handler.setup_page');

out_script (q {
var d = window.top.document;
__profile_in ($callee);

d.write ('<pre>' + data + '</pre>');
my $code = &$callee ($page);

__profile_out ($callee);

d.close ();
return $code;

}, $@);

return _ok ();
};

if ($@) {

warn "$@\n";

out_script (q {
var d = window.top.document;
d.write ('<pre>' + data + '</pre>');
d.close ();
}, $@);

return _ok ();

}

};

}
__profile_out ('handler.request' => {label => "type='$_REQUEST_VERBATIM{type}' id='$_REQUEST_VERBATIM{id}' action='$_REQUEST_VERBATIM{action}' id_user='$_USER->{id}'"}); warn "\n";

if ($_REQUEST {__suicide}) {
$r -> print (' ' x 8192);
CORE::exit (0);
}

return $code;

}
Expand All @@ -44,41 +71,33 @@ sub handler {

sub page_is_not_needed {

my $ptime = shift;
__profile_in ('handler.prelude');

setup_request_params (@_); $$ptime = __log_profilinig ($$ptime, '<setup_request_params>'); my $request_time = 1000 * (time - $first_time);

require_config ( ); $$ptime = __log_profilinig ($$ptime, '<require_config>');
our $i18n = i18n ();

sql_reconnect ( ); $$ptime = __log_profilinig ($$ptime, '<sql_reconnect>');
setup_request_params (@_);

require_model ( ); $$ptime = __log_profilinig ($$ptime, '<require_model>'); __log_request_profilinig ($request_time);
require_config ( );

authentication_is_needed ( ) or return 1; $$ptime = __log_profilinig ($$ptime, '<authentication_is_needed>');
sql_reconnect ( );

setup_user ( ) or return 1; $$ptime = __log_profilinig ($$ptime, '<setup_user>');
require_model ( );

return 0;

}
__profile_in ('handler.setup_user');

################################################################################
my $u = setup_user ();

__profile_out ('handler.setup_user');

sub setup_user {
__profile_out ('handler.prelude');

our $_USER = get_user ();

return 1 if $_USER -> {id} or $_REQUEST {type} =~ /(logon|_boot)/;

handle_request_of_type_kickout ();

return 0;
return $u ? 0 : 1;

}

################################################################################

sub authentication_is_needed {
sub setup_user {

if ($r -> uri =~ m{/(\w+)\.(css|gif|ico|js|html)$}) {

Expand Down Expand Up @@ -120,16 +139,22 @@ sub authentication_is_needed {
return 0;

}

our $_USER = get_user ();

return 1 if $_USER -> {id} or $_REQUEST {type} =~ /(logon|_boot)/;

handle_request_of_type_kickout ();

return 1;
return 0;

}

################################################################################

sub setup_request_params {

my $handler_time = time ();
__profile_in ('handler.setup_request_params');

$ENV {REMOTE_ADDR} = $ENV {HTTP_X_REAL_IP} if $ENV {HTTP_X_REAL_IP};

Expand All @@ -156,14 +181,6 @@ sub setup_request_params {
our %_COOKIE = (map {$_ => $_COOKIES {$_} -> value || ''} keys %_COOKIES);

set_cookie_for_root (client_cookie => $_COOKIE {client_cookie} || Digest::MD5::md5_hex (rand ()));

my $time = $r -> request_time ();

$time = __log_profilinig ($handler_time, '<get_request>');

our $first_time = $time;

$_REQUEST {__sql_time} = 0;

foreach my $k (keys %_REQUEST) {

Expand Down Expand Up @@ -226,7 +243,7 @@ sub setup_request_params {

setup_request_params_for_action () if $_REQUEST {action};

return $time;
__profile_out ('handler.setup_request_params');

}

Expand Down Expand Up @@ -537,62 +554,48 @@ sub handle_request_of_type_showing {

sub handler_finish {

$r -> pool -> cleanup_register (\&__log_request_finish_profilinig, {

id_request_log => $_REQUEST {_id_request_log},
out_html_time => $_REQUEST {__out_html_time},
application_time => 1000 * (time - $first_time) - $_REQUEST {__sql_time},
sql_time => $_REQUEST {__sql_time},
is_gzipped => $_REQUEST {__is_gzipped},

}) if $preconf -> {core_debug_profiling} > 2;

sql_disconnect () if $ENV {SCRIPT_NAME} eq '/__try__and__disconnect';

my $time = __log_profilinig ($first_time, "<TOTAL>\n");

__profile_in ('core.memory');
if (my $memory_usage = memory_usage ()) {

if (exists $preconf -> {core_memory_limit} && $memory_usage >> 20 > $preconf -> {core_memory_limit}) {
__log_profilinig ($time, sprintf ("<P. S. Memory limit of %s MiB exceeded: have %s MiB. This was the suicide note.>\n", $preconf -> {core_memory_limit}, $memory_usage >> 20));

__profile_out ('core.memory', {label => sprintf ("Memory limit of %s MiB exceeded: have %s MiB. This was the suicide note.", $preconf -> {core_memory_limit}, $memory_usage >> 20)});

$_REQUEST {__suicide} = 1;

}
else {

$preconf -> {_} -> {memory} -> {last} ||= $preconf -> {_} -> {memory} -> {first};

if ($preconf -> {core_debug_profiling}) {

__log_profilinig ($time, sprintf (
$preconf -> {_} -> {memory} -> {last} ||= $preconf -> {_} -> {memory} -> {first};

"<P. S. %s MiB (%s B: first + %s B; last + %s B)>\n",
__profile_out ('core.memory', {label => sprintf (

$memory_usage >> 20,
"%s MiB (%s B: first + %s B; last + %s B)",

$memory_usage,
$memory_usage >> 20,

$memory_usage - $preconf -> {_} -> {memory} -> {first},
$memory_usage,

$memory_usage - $preconf -> {_} -> {memory} -> {last},
$memory_usage - $preconf -> {_} -> {memory} -> {first},

));
$memory_usage - $preconf -> {_} -> {memory} -> {last},

}
)});

$preconf -> {_} -> {memory} -> {last} = $memory_usage;

}

}
else {

if ($_REQUEST {__suicide}) {
$r -> print (' ' x 8192);
CORE::exit (0);
__profile_out ('core.memory', {label => 'disabled'});

}

return _ok ();

}
Expand Down

0 comments on commit 00900c3

Please sign in to comment.