Menu
▾
▴
[Digir-cvs] SF.net SVN: digir:[2040] tapirlink/trunk
|
From: <rd...@us...> - 2014-02-05 13:01:30
|
Revision: 2040
http://sourceforge.net/p/digir/svn/2040
Author: rdg
Date: 2014-02-05 13:01:27 +0000 (Wed, 05 Feb 2014)
Log Message:
-----------
New code for time profiling on search operations
Modified Paths:
--------------
tapirlink/trunk/classes/TpDiagnostics.php
tapirlink/trunk/classes/TpResponse.php
tapirlink/trunk/classes/TpSearchResponse.php
tapirlink/trunk/www/localconfig_dist.php
tapirlink/trunk/www/tapir.php
tapirlink/trunk/www/tapir_globals.php
Modified: tapirlink/trunk/classes/TpDiagnostics.php
===================================================================
--- tapirlink/trunk/classes/TpDiagnostics.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/classes/TpDiagnostics.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -143,7 +143,7 @@
if ( _DEBUG )
{
- $duration = sprintf( '%0.4f', TpUtils::MicrotimeFloat()-INITIAL_TIMESTAMP );
+ $duration = sprintf( 'Total elapsed time: %0.4f', TpUtils::MicrotimeFloat()-INITIAL_TIMESTAMP );
TpDiagnostics::Append( DC_DURATION, $duration, DIAG_INFO );
if ( function_exists( 'memory_get_peak_usage' ) )
Modified: tapirlink/trunk/classes/TpResponse.php
===================================================================
--- tapirlink/trunk/classes/TpResponse.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/classes/TpResponse.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -67,6 +67,8 @@
function Process()
{
+ $start_time = ( TP_ENABLE_PROFILING ) ? TpUtils::MicrotimeFloat() : 0;
+
// In some cases it is necessary to replace headers (see "header" call
// inside TpXmlGenerator), so avoid echoing content straight away.
ob_start();
@@ -106,6 +108,8 @@
// Header should be always dynamic, leave it out from cache
$this->Header();
+ $start_time = $this->_AddDuration( $start_time, 'Header' );
+
if ( $this->mCacheable and TP_USE_CACHE and $this->mCacheLife )
{
$g_dlog->debug( 'Response cache is activated' );
@@ -131,11 +135,15 @@
$log_data = $this->_GetLogData();
$this->Log( $log_data );
+
+ $start_time = $this->_AddDuration( $start_time, 'Cached response' );
}
else
{
$this->Body();
+ $start_time = ( TP_ENABLE_PROFILING ) ? TpUtils::MicrotimeFloat() : 0;
+
// Note: better to place logging after Body() so that the SQL can
// also be logged.
$log_data = $this->_GetLogData();
@@ -143,6 +151,8 @@
$this->Log( $log_data );
$this->Footer();
+
+ $start_time = $this->_AddDuration( $start_time, 'Log and footer' );
}
}
@@ -181,6 +191,8 @@
$LogStruct->Initialize( $log_data );
$LogStruct->WriteRequestResult( $stats_log );
+
+ $start_time = $this->_AddDuration( $start_time, 'Statistics' );
}
ob_end_flush();
@@ -429,5 +441,19 @@
} // end of member function _GetLogData
+ function _AddDuration( $start, $msg )
+ {
+ if ( TP_ENABLE_PROFILING )
+ {
+ $end = TpUtils::MicrotimeFloat();
+ $duration = sprintf( '%s: %0.4f', $msg, $end-$start );
+ TpDiagnostics::Append( DC_DURATION, $duration, DIAG_INFO );
+ return $end;
+ }
+
+ return 0;
+
+ } // end of member function _AddDuration
+
} // end of TpResponse
?>
\ No newline at end of file
Modified: tapirlink/trunk/classes/TpSearchResponse.php
===================================================================
--- tapirlink/trunk/classes/TpSearchResponse.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/classes/TpSearchResponse.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -67,6 +67,8 @@
function Body()
{
+ $start_time = ( TP_ENABLE_PROFILING ) ? TpUtils::MicrotimeFloat() : 0;
+
global $g_dlog;
$g_dlog->debug( '[Search Body]' );
@@ -101,6 +103,8 @@
$max_levels = $r_settings->GetMaxElementLevels();
+ $start_time = $this->_AddDuration( $start_time, 'Search config' );
+
// Output model
$r_output_model =& $parameters->GetOutputModel();
@@ -208,6 +212,8 @@
return;
}
+ $start_time = $this->_AddDuration( $start_time, 'Output model setup' );
+
// Prepare SQL builder
$g_dlog->debug( '--------------' );
@@ -322,6 +328,8 @@
$sql_builder->AddRecordSource( $r_tables->GetStructure() );
+ $start_time = $this->_AddDuration( $start_time, 'SQL builder' );
+
// DB connection
if ( ! $r_data_source->Validate() )
@@ -334,6 +342,8 @@
$db_encoding = $r_data_source->GetEncoding();
+ $start_time = $this->_AddDuration( $start_time, 'DB connection' );
+
// Filter
$filter = $parameters->GetFilter();
@@ -417,6 +427,8 @@
$limit = $max_repetitions;
}
+ $start_time = $this->_AddDuration( $start_time, 'Filter' );
+
// Count total matched records, if requested
$matched = 0;
@@ -497,6 +509,8 @@
$g_dlog->debug( 'Caching count SQL: '.$matched );
}
}
+
+ $start_time = $this->_AddDuration( $start_time, 'Record count' );
}
// Retrieve records
@@ -507,8 +521,14 @@
$encoded_sql = TpServiceUtils::EncodeSql( $this->mMainSql, $db_encoding );
+ $this->_AddDuration( $start_time, 'Search query setup' );
+
+ $start_time = ( TP_ENABLE_PROFILING ) ? TpUtils::MicrotimeFloat() : 0;
+
$result_set =& $cn->SelectLimit( $encoded_sql, $limit+1, $start );
+ $start_time = $this->_AddDuration( $start_time, 'Search query' );
+
if ( ! is_object( $result_set ) )
{
$err = $cn->ErrorMsg();
@@ -556,6 +576,8 @@
echo $main_content;
+ $start_time = $this->_AddDuration( $start_time, 'Search XML output' );
+
// Search Summary
if ( $this->mRequest->GetEnvelope() )
@@ -581,6 +603,8 @@
echo ' />';
echo "\n</search>";
+
+ $start_time = $this->_AddDuration( $start_time, 'Search XML summary' );
}
$result_set->Close();
Modified: tapirlink/trunk/www/localconfig_dist.php
===================================================================
--- tapirlink/trunk/www/localconfig_dist.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/www/localconfig_dist.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -83,6 +83,12 @@
//define('_DEBUG', true);
/**
+* Set this true to enable profiling. This will ouput messages about
+* durations of the main tasks (search operations only).
+*/
+//define('TP_ENABLE_PROFILING', true);
+
+/**
* Set to true if you want to store detailed debugging information in a separate file
*/
//define('TP_LOG_DEBUG', true);
Modified: tapirlink/trunk/www/tapir.php
===================================================================
--- tapirlink/trunk/www/tapir.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/www/tapir.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -232,6 +232,12 @@
die();
}
+if ( TP_ENABLE_PROFILING )
+{
+ $duration = sprintf( 'Initial setup: %0.4f', TpUtils::MicrotimeFloat()-INITIAL_TIMESTAMP );
+ TpDiagnostics::Append( DC_DURATION, $duration, DIAG_INFO );
+}
+
$response->Process();
exit();
Modified: tapirlink/trunk/www/tapir_globals.php
===================================================================
--- tapirlink/trunk/www/tapir_globals.php 2013-11-11 16:37:32 UTC (rev 2039)
+++ tapirlink/trunk/www/tapir_globals.php 2014-02-05 13:01:27 UTC (rev 2040)
@@ -79,6 +79,11 @@
define( 'TP_WWW_DIR', $root_dir );
}
+if ( ! defined( 'TP_ENABLE_PROFILING' ) )
+{
+ define( 'TP_ENABLE_PROFILING', false );
+}
+
// The full path to the directory used to contain configuration.
if ( ! defined( 'TP_CONFIG_DIR' ) ) {
This was sent by the SourceForge.net collaborative development platform, the world's largest Open Source development site.
|
