diff --git a/Eludia/Content.pm b/Eludia/Content.pm index 86292e2f7..26850e681 100755 --- a/Eludia/Content.pm +++ b/Eludia/Content.pm @@ -9,6 +9,7 @@ use Eludia::Content::HTTP; use Eludia::Content::Validators; use Eludia::Content::Templates; use Eludia::Content::Tie; +use Eludia::Content::Profiling; ############################################################################# @@ -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) = @_; diff --git a/Eludia/Content/Auth.pm b/Eludia/Content/Auth.pm index 0a670c438..1842933fa 100755 --- a/Eludia/Content/Auth.pm +++ b/Eludia/Content/Auth.pm @@ -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, ' '); +# __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}); @@ -93,7 +95,7 @@ sub get_user_with_fixed_session { lc_hashref ($user); - __log_profilinig ($time, ' '); +# __profile_out ('auth.get_user', {label => "$user->{id} ($user->{label})"}); $user -> {id} or return undef; diff --git a/Eludia/Content/Handler.pm b/Eludia/Content/Handler.pm index 7e26521f2..312ed5c60 100755 --- a/Eludia/Content/Handler.pm +++ b/Eludia/Content/Handler.pm @@ -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, ''); + $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 ('
' + data + '
'); + 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 ('
' + data + '
'); + + 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; } @@ -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, ''); my $request_time = 1000 * (time - $first_time); - - require_config ( ); $$ptime = __log_profilinig ($$ptime, ''); + our $i18n = i18n (); - sql_reconnect ( ); $$ptime = __log_profilinig ($$ptime, ''); + setup_request_params (@_); - require_model ( ); $$ptime = __log_profilinig ($$ptime, ''); __log_request_profilinig ($request_time); + require_config ( ); - authentication_is_needed ( ) or return 1; $$ptime = __log_profilinig ($$ptime, ''); + sql_reconnect ( ); - setup_user ( ) or return 1; $$ptime = __log_profilinig ($$ptime, ''); + 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)$}) { @@ -120,8 +139,14 @@ 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; } @@ -129,7 +154,7 @@ sub authentication_is_needed { 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}; @@ -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, ''); - - our $first_time = $time; - - $_REQUEST {__sql_time} = 0; foreach my $k (keys %_REQUEST) { @@ -226,7 +243,7 @@ sub setup_request_params { setup_request_params_for_action () if $_REQUEST {action}; - return $time; + __profile_out ('handler.setup_request_params'); } @@ -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, "\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 ("\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}; - "\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 (); } diff --git a/Eludia/Content/ModuleTools.pm b/Eludia/Content/ModuleTools.pm index 378450aa1..60fa84973 100755 --- a/Eludia/Content/ModuleTools.pm +++ b/Eludia/Content/ModuleTools.pm @@ -48,6 +48,8 @@ sub require_both ($) { sub require_config { + __profile_in ('require.config'); + unless ($preconf -> {_} -> {site_conf} -> {path}) { $preconf -> {_} -> {site_conf} -> {path} = $preconf -> {_} -> {docroot}; @@ -102,6 +104,8 @@ sub require_config { fill_in (); + __profile_out ('require.config'); + } ################################################################################ @@ -120,6 +124,8 @@ sub get_item_of_ ($) { sub require_model { + __profile_in ('require.model'); + my $core_was_ok = $model_update -> {core_ok}; sql_assert_core_tables (); @@ -145,6 +151,8 @@ sub require_model { $core_was_ok or require_scripts (); + __profile_out ('require.model'); + } ################################################################################ @@ -193,7 +201,7 @@ sub require_scripts_of_type ($) { foreach my $dir (grep {-d} map {$_ . $postfix} _INC ()) { - my $time = time; + __profile_in ("require.scripts.$script_type" => {label => $dir}); my @scripts = (); my $name2def = {}; @@ -228,7 +236,7 @@ sub require_scripts_of_type ($) { if (@scripts == 0) { - __log_profilinig ($time, " $dir/.* <= " . localtime_to_iso ($__last_update)); + __profile_out ("require.scripts.$script_type"); next; @@ -240,7 +248,7 @@ sub require_scripts_of_type ($) { if (%$needed_scripts == 0) { - __log_profilinig ($time, " require_scripts_of_type $script_type: all scripts in $dir are filtered by 'checksums' (which are, in fact, timestamps)."); + __profile_out ("require.scripts.$script_type"); next; @@ -248,7 +256,7 @@ sub require_scripts_of_type ($) { foreach my $script (sort {$a -> {last_modified} <=> $b -> {last_modified}} grep {$needed_scripts -> {$_ -> {path}}} @scripts) { - my $time = time (); + __profile_in ("require.scripts.$script_type.file", {label => $script -> {path}}); if ($script_type eq 'model') { @@ -271,13 +279,13 @@ sub require_scripts_of_type ($) { } - $time = __log_profilinig ($time, " $script->{path} fired"); + __profile_out ("require.scripts.$script_type.file"); } checksum_write ($checksum_kind, $new_checksums); - __log_profilinig ($time, " require_scripts_of_type $script_type done in $dir"); + __profile_out ("require.scripts.$script_type"); } @@ -291,7 +299,7 @@ sub require_scripts { return if $_REQUEST {__don_t_require_scripts}; - my $time = time; + __profile_in ('require.scripts'); my $file_name; @@ -327,7 +335,7 @@ sub require_scripts { close (CONFIG); - __log_profilinig ($time, " require_scripts done"); + __profile_out ('require.scripts'); $_REQUEST {__don_t_require_scripts} = 1; @@ -446,10 +454,10 @@ sub last_modified_time_if_refresh_is_needed { sub require_fresh { - local $time = time; - my ($module_name) = @_; + __profile_in ('require.module' => {label => $module_name}); + my $local_file_name = $module_name; $local_file_name =~ s{(::)+}{\/}g; @@ -468,15 +476,33 @@ sub require_fresh { my @file_names = grep {-f} map {"${_}$local_file_name.pm"} @inc; - @file_names > 0 or return "Module $module_name not found in " . (join '; ', @inc) . "\n"; + if (@file_names == 0) { + + __profile_out ('require.module'); + + return; - (grep {last_modified_time_if_refresh_is_needed ($_)} @file_names) > 0 or return; + } foreach my $file_name (reverse @file_names) { - delete $INC_FRESH_BY_PATH {$file_name}; + __profile_in ('require.file'); + + my $last_recorded_time = $INC_FRESH_BY_PATH {$file_name}; + + my ($dev, $ino, $mode, $nlink, $uid, $gid, $rdev, $size, $atime, $mtime, $ctime, $blksize, $blocks) = stat ($file_name); + + my $last_modified_iso = localtime_to_iso ($mtime); + + if ($mtime <= $last_recorded_time) { + + __profile_out ('require.file' => {label => "$file_name = $last_modified_iso"}); + + next; + + } - my $last_modified = last_modified_time_if_refresh_is_needed ($file_name); + delete $INC_FRESH_BY_PATH {$file_name}; if ($type eq 'menu') { @@ -512,17 +538,13 @@ sub require_fresh { die "$module_name: " . $@ if $@; - $INC_FRESH {$module_name} = $INC_FRESH_BY_PATH {$file_name} = $last_modified; - - if ($preconf -> {core_debug_profiling}) { - - my $message = require_fresh_message ($file_name); + $INC_FRESH {$module_name} = $INC_FRESH_BY_PATH {$file_name} = $mtime; - $time = __log_profilinig ($time, " $message -> " . localtime_to_iso ($last_modified)); - - } + __profile_out ('require.file' => {label => "$file_name -> $last_modified_iso"}); } + + __profile_out ('require.module'); } @@ -577,36 +599,14 @@ sub call_for_role { if ($name_to_call) { - $_REQUEST {__benchmarks_selected} = 0; - + __profile_in ("call.$name_to_call"); + my $result = &$name_to_call (@_); - - if ($preconf -> {core_debug_profiling} > 1) { - - my $id = sql_select_id ($conf->{systables}->{__benchmarks} => {fake => 0, label => $sub_name}); - - my $benchmarks_table = sql_table_name ($conf->{systables}->{__benchmarks}); - - sql_do ( - "UPDATE $benchmarks_table SET cnt = cnt + 1, ms = ms + ?, selected = selected + ? WHERE id = ?", - int(1000 * (time - $time)), - $_REQUEST {__benchmarks_selected}, - $id, - ); - - - sql_do ( - "UPDATE $benchmarks_table SET mean = ms / cnt, mean_selected = selected / cnt WHERE id = ?", - $id, - ); - - } - elsif ($preconf -> {core_debug_profiling} == 1) { - __log_profilinig ($time, ' ' . $name_to_call); - } + + __profile_out ("call.$name_to_call"); return $result; - + } else { diff --git a/Eludia/Content/Profiling.pm b/Eludia/Content/Profiling.pm new file mode 100644 index 000000000..b2bab259c --- /dev/null +++ b/Eludia/Content/Profiling.pm @@ -0,0 +1,169 @@ +################################################################################ + +sub __profile_in { + + ref $preconf -> {core_debug_profiling} eq HASH or $preconf -> {core_debug_profiling} = { + + in => sub {}, + + out => sub { + + my ($old_options, $new_options) = @_; + + my $now = $new_options -> {__time}; + + my ($sec, $min, $hour, $day, $mon, $year) = localtime ($now); + + my $message = sprintf ("[%04d-%02d-%02d %02d:%02d:%02d:%03d $$] ", $year + 1900, $mon + 1, $day, $hour, $min, $sec, int (1000 * ($now - int $now))); + + $message .= ' ' x $old_options -> {__level}; + + $message .= sprintf ('%6.1f ms ', $new_options -> {__duration}); + + $message .= ' ' x (7 - $old_options -> {__level}); + + $message .= sprintf ("%-30s ", $old_options -> {__type}); + + if ($new_options -> {__type} ne $old_options -> {__type}) { + + $message .= '[ABORT]'; + + } + else { + + my $comment = $new_options -> {label} || $old_options -> {label}; + + $comment =~ s{\s+}{ }gsm; + + $message .= $comment; + + } + + $message .= "\n"; + + warn $message; + + }, + + }; + + my ($type, $options) = @_; + + $options -> {__time} = time (); + $options -> {__type} = $type; + + push @_PROFILING_STACK, $options; + + $options -> {__level} = @_PROFILING_STACK - 1; + + &{$preconf -> {core_debug_profiling} -> {in}} ($options); + +} + +################################################################################ + +sub __profile_out { + + my ($type, $new_options) = @_; + + $new_options -> {__time} = time (); + + @_PROFILING_STACK > 0 or warn "Profiling skewed: stack is empty\n"; + + while (@_PROFILING_STACK) { + + my $old_options = pop @_PROFILING_STACK; + + $new_options -> {__type} = $type; + + $new_options -> {__duration} = 1000 * ($new_options -> {__time} - $old_options -> {__time}); + + &{$preconf -> {core_debug_profiling} -> {out}} ($old_options, $new_options); + + last if $old_options -> {__type} eq $type; + + } + +} + +################################################################################ + +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 __log_request_profilinig { + + my ($request_time) = @_; + + return unless ($preconf -> {core_debug_profiling} > 2 && $model_update -> {core_ok}); + + my $c = $r -> connection; + + $_REQUEST {_id_request_log} = sql_do_insert ($conf -> {systables} -> {__request_benchmarks}, { + id_user => $_USER -> {id}, + ip => $ENV {REMOTE_ADDR}, + ip_fw => $ENV {HTTP_X_FORWARDED_FOR}, + fake => 0, + type => $_REQUEST {type}, + mac => get_mac (), + request_time => int ($request_time), + connection_id => $c -> id (), + connection_no => $c -> keepalives (), + }); + + my $request_benchmarks_table = sql_table_name ($conf -> {systables} -> {__request_benchmarks}); + + sql_do ("UPDATE $request_benchmarks_table SET params = ? WHERE id = ?", + Data::Dumper -> Dump ([\%_REQUEST], ['_REQUEST']), $_REQUEST {_id_request_log}); + +} + +################################################################################ + +sub __log_request_finish_profilinig { + + my ($options) = @_; + + return + unless ($preconf -> {core_debug_profiling} > 2 && $model_update -> {core_ok}); + + my $time = time; + + my $request_benchmarks_table = sql_table_name ($conf -> {systables} -> {__request_benchmarks}); + + sql_do ("UPDATE $request_benchmarks_table SET application_time = ?, sql_time = ?, response_time = ?, bytes_sent = ?, is_gzipped = ? WHERE id = ?", + int ($options -> {application_time}), + int ($options -> {sql_time}), + $options -> {out_html_time} ? int (1000 * (time - $options -> {out_html_time})) : 0, + $r -> bytes_sent, + $options -> {is_gzipped}, + $options -> {id_request_log}, + ); + +} + +1; \ No newline at end of file diff --git a/Eludia/Presentation.pm b/Eludia/Presentation.pm index e06d445cb..3df3bdc91 100644 --- a/Eludia/Presentation.pm +++ b/Eludia/Presentation.pm @@ -598,11 +598,13 @@ sub adjust_esc { sub draw_form { my ($options, $data, $fields) = @_; - - my $time = time; - + return '' if $options -> {off} && $data; + $options -> {path} ||= $data -> {path}; + + __profile_in ('draw.form' => {label => ref $options -> {path} eq ARRAY ? $options -> {path} -> [0] -> {name} : undef}); + $options -> {hr} = defined $options -> {hr} ? $options -> {hr} : 10; $options -> {hr} = $_REQUEST {__tree} ? '' : draw_hr (height => $options -> {hr}); @@ -614,7 +616,13 @@ sub draw_form { $options -> {name} ||= 'form'; - !$_REQUEST {__only_form} or $_REQUEST {__only_form} eq $options -> {name} or return ''; + unless (!$_REQUEST {__only_form} or $_REQUEST {__only_form} eq $options -> {name}) { + + __profile_out ('draw.form'); + + return ''; + + } $options -> {no_esc} = 1 if $apr -> param ('__last_query_string') < 0 && !$_REQUEST {__edit}; $options -> {target} ||= 'invisible'; @@ -682,9 +690,7 @@ sub draw_form { } $options -> {rows} = \@rows; - - $options -> {path} ||= $data -> {path}; - + $options -> {path} = ($options -> {path} && !$_REQUEST{__no_navigation}) ? draw_path ($options, $options -> {path}) : ''; delete $options -> {menu} if $_REQUEST {__edit}; @@ -766,7 +772,7 @@ sub draw_form { my $html = $_SKIN -> draw_form ($options); - __log_profilinig ($time, sprintf (" draw_form")); + __profile_out ('draw.form'); return $html; @@ -1678,8 +1684,6 @@ sub draw_table_header_cell { sub draw_table { - my $time = time; - return '' if $_REQUEST {__only_form}; my $headers = []; @@ -1690,6 +1694,8 @@ sub draw_table { my ($tr_callback, $list, $options) = @_; + __profile_in ('draw.table' => {label => $options -> {title} -> {label}}); + if ($options -> {no_order}) { $_REQUEST {__no_order} = 1; } else { @@ -1754,7 +1760,13 @@ sub draw_table { $options -> {name} ||= 'form'; $options -> {target} ||= 'invisible'; - return '' if $options -> {off}; + if ($options -> {off}) { + + __profile_out ('draw.table' => {label => "[OFF] $options->{title}->{label}"}); + + return ''; + + } $_REQUEST {__salt} ||= rand () * time (); $_REQUEST {__uri_root_common} ||= $_REQUEST {__uri} . '?salt=' . $_REQUEST {__salt} . '&sid=' . $_REQUEST {sid}; @@ -1917,8 +1929,8 @@ sub draw_table { delete $_REQUEST {__gantt_from_year}; delete $_REQUEST {__gantt_to_year}; - - __log_profilinig ($time, sprintf (" draw_table")); + + __profile_out ('draw.table'); return $html; @@ -2287,15 +2299,18 @@ sub draw_error_page { my $page = $_[0]; $_REQUEST {error} ||= $_[1]; - - Carp::cluck ($_REQUEST {error}); - + if ($_REQUEST {error} =~ s{^\#(\w+)\#\:}{}) { $page -> {error_field} = $1; ($_REQUEST {error}) = split / at/sm, $_REQUEST {error}; + } + else { + + Carp::cluck ($_REQUEST {error}); + } setup_skin (); @@ -2465,7 +2480,7 @@ sub gzip_if_it_is_needed (\$) { or return; - my $time = time; + __profile_in ('core.gzip'); eval {$$ref_html = gzip_in_memory ($$ref_html)}; @@ -2473,7 +2488,7 @@ sub gzip_if_it_is_needed (\$) { my $ratio = int (10000 * ($old_size - $new_size) / $old_size) / 100; - __log_profilinig ($time, sprintf (" %d, %.2f\%>", $old_size, $new_size, 100 * ($old_size - $new_size) / $old_size)); + __profile_out ('core.gzip' => {label => sprintf ("%d -> %d, %.2f\%", $old_size, $new_size, 100 * ($old_size - $new_size) / $old_size)}); $r -> content_encoding ('gzip'); @@ -2521,7 +2536,7 @@ sub out_html { $html and !$_REQUEST {__response_sent} or return; - $_REQUEST {__out_html_time} = my $time = time; + __profile_in ('core.out_html'); if ($conf -> {core_sweep_spaces}) { $html =~ s{^\s+}{}gsm; @@ -2550,7 +2565,7 @@ sub out_html { $_REQUEST {__response_sent} = 1; - __log_profilinig ($time, " "); + __profile_out ('core.out_html' => {label => "$length bytes"}); } @@ -2682,7 +2697,7 @@ sub check_static_files { return if $_SKIN -> {options} -> {no_static}; $r or return; - my $time = time; + __profile_in ('core.check_static_files'); my $skin_root = $r -> document_root () . $_REQUEST {__static_url}; @@ -2698,7 +2713,7 @@ sub check_static_files { $_SKIN -> {static_ok} -> {$_NEW_PACKAGE} = 1; - __log_profilinig ($time, " check_static_files: at $version"); + __profile_out ('core.check_static_files' => {label => "= $version"}); return; @@ -2784,7 +2799,7 @@ sub check_static_files { } - __log_profilinig ($time, ' check_static_files'); + __profile_out ('core.check_static_files' => {label => "-> $Eludia::VERSION"}); } diff --git a/Eludia/SQL.pm b/Eludia/SQL.pm index c324dc156..6b7db765b 100644 --- a/Eludia/SQL.pm +++ b/Eludia/SQL.pm @@ -187,7 +187,7 @@ sub sql_assert_core_tables { return if $model_update -> {core_ok}; -my $time = time; + __profile_in ('sql.assert_core_tables'); $model_update -> assert ( @@ -215,7 +215,7 @@ my $time = time; $model_update -> {core_ok} = 1; -__log_profilinig ($time, ' '); + __profile_out ('sql.assert_core_tables'); } @@ -320,18 +320,24 @@ sub sql_ping { sub sql_reconnect { -my $time = time; + __profile_in ('core.sql.reconnect'); our $db, $model_update, $SQL_VERSION; if ($db && ($preconf -> {no_model_update} || ($model_update && $model_update -> {core_ok}))) { - sql_ping () and return + if (sql_ping ()) { + + __profile_out ('core.sql.reconnect', {label => 'ping OK'}); + + return; + + } -$time = __log_profilinig ($time, ' sql_reconnect: ping OK'); - } + __profile_in ('core.sql.connect', {label => $preconf -> {db_dsn}}); + $db = DBI -> connect ($preconf -> {db_dsn}, $preconf -> {db_user}, $preconf -> {db_password}, { PrintError => 0, RaiseError => 1, @@ -353,10 +359,12 @@ $time = __log_profilinig ($time, ' sql_reconnect: ping OK'); } -$time = __log_profilinig ($time, " sql_reconnect: connected to $preconf->{db_dsn}"); - + __profile_out ('core.sql.connect'); + unless ($INC_FRESH {db_driver}) { + __profile_in ('core.sql.driver'); + my $driver_name = $db -> get_info ($GetInfoType {SQL_DBMS_NAME}); $driver_name =~ s{\W}{}gsm; @@ -373,15 +381,13 @@ $time = __log_profilinig ($time, " sql_reconnect: connected to $preconf->{db_ds $SQL_VERSION = {driver => $driver_name}; -$time = __log_profilinig ($time, " sql_reconnect: $driver_name is loaded"); + __profile_out ('core.sql.driver', {label => $driver_name}); } delete $SQL_VERSION -> {_}; sql_version (); - -$time = __log_profilinig ($time, " sql_reconnect: driver version is $SQL_VERSION->{string}"); unless ($preconf -> {no_model_update}) { @@ -398,12 +404,12 @@ $time = __log_profilinig ($time, " sql_reconnect: driver version is $SQL_VERSIO schema => $preconf -> {db_schema}, ); -$time = __log_profilinig ($time, ' sql_reconnect: $model_update created'); - } - - } + } + + __profile_out ('core.sql.reconnect', {label => $SQL_VERSION -> {string}}); + } ################################################################################ @@ -948,16 +954,6 @@ EOS } -################################################################################ - -sub __log_sql_profilinig { - - my ($options) = @_; - - $_REQUEST {__sql_time} += 1000 * (time - $options -> {time}); - -} - ################################################################################ sub sql_extract_params { @@ -1096,59 +1092,6 @@ sub sql_adjust_fake_filter { ################################################################################ -sub __log_request_profilinig { - - my ($request_time) = @_; - - return unless ($preconf -> {core_debug_profiling} > 2 && $model_update -> {core_ok}); - - my $c = $r -> connection; - - $_REQUEST {_id_request_log} = sql_do_insert ($conf -> {systables} -> {__request_benchmarks}, { - id_user => $_USER -> {id}, - ip => $ENV {REMOTE_ADDR}, - ip_fw => $ENV {HTTP_X_FORWARDED_FOR}, - fake => 0, - type => $_REQUEST {type}, - mac => get_mac (), - request_time => int ($request_time), - connection_id => $c -> id (), - connection_no => $c -> keepalives (), - }); - - my $request_benchmarks_table = sql_table_name ($conf -> {systables} -> {__request_benchmarks}); - - sql_do ("UPDATE $request_benchmarks_table SET params = ? WHERE id = ?", - Data::Dumper -> Dump ([\%_REQUEST], ['_REQUEST']), $_REQUEST {_id_request_log}); - -} - -################################################################################ - -sub __log_request_finish_profilinig { - - my ($options) = @_; - - return - unless ($preconf -> {core_debug_profiling} > 2 && $model_update -> {core_ok}); - - my $time = time; - - my $request_benchmarks_table = sql_table_name ($conf -> {systables} -> {__request_benchmarks}); - - sql_do ("UPDATE $request_benchmarks_table SET application_time = ?, sql_time = ?, response_time = ?, bytes_sent = ?, is_gzipped = ? WHERE id = ?", - int ($options -> {application_time}), - int ($options -> {sql_time}), - $options -> {out_html_time} ? int (1000 * (time - $options -> {out_html_time})) : 0, - $r -> bytes_sent, - $options -> {is_gzipped}, - $options -> {id_request_log}, - ); - -} - -################################################################################ - sub sql_select_ids { my ($sql, @params) = @_; diff --git a/Eludia/SQL/Dialect/Oracle.pm b/Eludia/SQL/Dialect/Oracle.pm index e24f97f2a..899fd795c 100644 --- a/Eludia/SQL/Dialect/Oracle.pm +++ b/Eludia/SQL/Dialect/Oracle.pm @@ -109,6 +109,8 @@ sub sql_execute { my ($st, @params) = sql_prepare (@_); + __profile_in ('sql.execute'); + my $affected; my $last_i = -1; @@ -138,6 +140,8 @@ sub sql_execute { } + __profile_out ('sql.execute', {label => $st -> {Statement} . ' ' . (join ', ', map {$db -> quote ($_)} @params)}); + return wantarray ? ($st, $affected) : $st; } @@ -146,13 +150,13 @@ sub sql_execute { sub sql_prepare { + __profile_in ('sql.prepare'); + my ($sql, @params) = @_; $sql =~ s{^\s+}{}; $sql =~ s{[\015\012]+}{$/}gs; - -#print STDERR "sql_prepare (pid=$$): $sql\n"; - + my $qoute = '"'; if ($sql =~ /^(\s*SELECT.*FROM\s+)(.*)$/is) { @@ -162,7 +166,7 @@ sub sql_prepare { if ($tables_reference =~ /^(.*)((WHERE|GROUP|ORDER).*)$/is) { ($tables_reference, $tail) = ($1, $2); } -# print "head: $head\ntables_reference: $tables_reference\ntail: $tail\n\n"; + my @table_names; if ($tables_reference =~ s/^(_\w+)/$qoute$1$qoute/) { push (@table_names, $1); @@ -171,7 +175,6 @@ sub sql_prepare { push (@table_names, $1) while ($tables_reference =~ s/JOIN\s*(_\w+)/JOIN $qoute$1$qoute/ig); $sql = $head . $tables_reference . $tail; foreach my $table_name (@table_names) { -# print "table_name: $table_name\n"; $sql =~ s/(\W)($table_name)\./$1$qoute$2$qoute\./g; } } @@ -223,6 +226,8 @@ sub sql_prepare { } + __profile_out ('sql.prepare', {label => $sql}); + return ($st, @params); } @@ -240,8 +245,6 @@ sub sql_do { (my $st, $affected) = sql_execute ($sql, @params); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql, selected => $affected}); } @@ -284,8 +287,6 @@ sub sql_execute_procedure { } $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql, selected => 0}); } @@ -326,6 +327,8 @@ sub sql_select_all_cnt { my $cnt = 0; my @result = (); + __profile_in ('sql.fetch'); + while (my $i = $st -> fetchrow_hashref ()) { $cnt++; @@ -336,15 +339,13 @@ sub sql_select_all_cnt { push @result, lc_hashref ($i); } + + __profile_out ('sql.fetch', {label => $st -> rows}); $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => @result + 0}); - - $sql =~ s{ORDER BY.*}{}ism; - my $cnt = 0; if ($sql =~ /(\s+GROUP\s+BY|\s+UNION\s+)/i) { @@ -390,6 +391,8 @@ sub sql_select_all { my $st = sql_execute ($sql, @params); my $cnt = 0; + __profile_in ('sql.fetch'); + while (my $r = $st -> fetchrow_hashref) { $cnt++; @@ -401,6 +404,8 @@ sub sql_select_all { } + __profile_out ('sql.fetch', {label => $st -> rows}); + $result = \@temp_result; $st -> finish; @@ -411,19 +416,19 @@ sub sql_select_all { return $st if $options -> {no_buffering}; + __profile_in ('sql.fetch'); + $result = $st -> fetchall_arrayref ({}); + __profile_out ('sql.fetch', {label => 0 + @$result}); + $st -> finish; } - __log_sql_profilinig ({time => $time, sql => $sql, selected => @$result + 0}); - foreach my $i (@$result) { lc_hashref ($i); } - - $_REQUEST {__benchmarks_selected} += @$result; return $result; @@ -453,7 +458,6 @@ sub sql_select_all_hash { } $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => (keys %$result) + 0}); return $result; @@ -508,8 +512,6 @@ sub sql_select_col { $st -> finish; } - - __log_sql_profilinig ({time => $time, sql => $sql, selected => @result + 0}); return @result; @@ -596,8 +598,6 @@ sub sql_select_hash { my $result = $st -> fetchrow_hashref (); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql_or_table_name, selected => 1}); return lc_hashref ($result); @@ -618,8 +618,6 @@ sub sql_select_array { my @result = $st -> fetchrow_array (); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql_or_table_name, selected => 1}); return wantarray ? @result : $result [0]; @@ -674,8 +672,6 @@ sub sql_select_scalar { } - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $result [0]; } @@ -922,8 +918,6 @@ EOS sql_do ($sql, @params); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $pairs -> {id}; } @@ -942,8 +936,6 @@ EOS $st -> execute; $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $id; } @@ -1030,8 +1022,6 @@ sub sql_download_file { $st -> finish (); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - } else { download_file ($options); @@ -1151,8 +1141,6 @@ sub sql_select_loop { $st -> finish (); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - } ################################################################################# diff --git a/Eludia/SQL/Dialect/PostgreSQL.pm b/Eludia/SQL/Dialect/PostgreSQL.pm index 6493366f7..9d4b2bf4d 100644 --- a/Eludia/SQL/Dialect/PostgreSQL.pm +++ b/Eludia/SQL/Dialect/PostgreSQL.pm @@ -105,8 +105,6 @@ sub sql_do { (my $st, $affected) = sql_execute ($sql, @params); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql, selected => $affected}); } @@ -149,8 +147,6 @@ sub sql_do { # } # $st -> finish; - -# __log_sql_profilinig ({time => $time, sql => $sql, selected => 0}); #} @@ -189,8 +185,6 @@ sub sql_select_all_cnt { $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => @result + 0}); - $sql =~ s{ORDER BY.*}{}ism; $sql =~ s/SELECT.*?[\n\s]+FROM[\n\s]+/SELECT COUNT(*) FROM /ism; my $cnt = sql_select_scalar ($sql, @params); @@ -229,8 +223,6 @@ sub sql_select_all { $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => @$result + 0}); - $_REQUEST {__benchmarks_selected} += @result; return \@result; @@ -263,8 +255,6 @@ sub sql_select_all_hash { $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => (keys %$result) + 0}); - return $result; } @@ -288,8 +278,6 @@ sub sql_select_col { } $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql, selected => @result + 0}); return @result; @@ -369,8 +357,6 @@ sub sql_select_hash { my $result = $st -> fetchrow_hashref (); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql_or_table_name, selected => 1}); return lc_hashref ($result); @@ -391,8 +377,6 @@ sub sql_select_array { my @result = $st -> fetchrow_array (); $st -> finish; - - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); return wantarray ? @result : $result [0]; @@ -416,8 +400,6 @@ sub sql_select_scalar { $st -> finish; - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $result [0]; } @@ -644,8 +626,6 @@ EOS sql_do ("INSERT INTO $table_name ($fields) VALUES ($args)", @params); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $pairs -> {id}; } @@ -653,8 +633,6 @@ EOS my $id = sql_select_scalar ("INSERT INTO $table_name ($fields) VALUES ($args) RETURNING id", @params); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - return $id; } @@ -741,8 +719,6 @@ sub sql_download_file { # $st -> finish (); -# __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - # } # else { download_file ($options); @@ -860,8 +836,6 @@ sub sql_select_loop { $st -> finish (); - __log_sql_profilinig ({time => $time, sql => $sql, selected => 1}); - } ################################################################################# diff --git a/Eludia/SQL/TheSqlFunction.pm b/Eludia/SQL/TheSqlFunction.pm index 7ca6004c6..f318af850 100644 --- a/Eludia/SQL/TheSqlFunction.pm +++ b/Eludia/SQL/TheSqlFunction.pm @@ -1029,6 +1029,8 @@ sub sql { my $n = 0; + __profile_in ('sql.fetch'); + while (my $r = $st -> fetchrow_hashref) { $n ++; @@ -1045,6 +1047,8 @@ sub sql { } + __profile_out ('sql.fetch', {label => $st -> rows}); + $st -> finish; my $sql_cnt = "SELECT COUNT(*)\n " @@ -1059,8 +1063,12 @@ sub sql { $st = sql_execute ($sql_cnt, @params); + __profile_in ('sql.fetch'); + my ($cnt) = $st -> fetchrow_array; + __profile_out ('sql.fetch', {label => $st -> rows}); + $st -> finish; @result = ($records, $cnt, $limit -> [1]);