Skip to content

Commit

Permalink
Merge pull request #40399 from elpaso/server-profiler
Browse files Browse the repository at this point in the history 
Server profiler
  • Loading branch information
@elpaso
elpaso committed Dec 4, 2020
2 parents def587f + d934c4f commit 6d2be40
Show file tree
Hide file tree
Showing 4 changed files with 195 additions and 126 deletions.
16 changes: 15 additions & 1 deletion python/server/auto_generated/qgsserversettings.sip.in
View file
Expand Up @@ -52,7 +52,8 @@ Provides some enum describing the environment currently supported for configurat
QGIS_SERVER_TRUST_LAYER_METADATA,
QGIS_SERVER_DISABLE_GETPRINT,
QGIS_SERVER_LANDING_PAGE_PROJECTS_DIRECTORIES,
QGIS_SERVER_LANDING_PAGE_PROJECTS_PG_CONNECTIONS
QGIS_SERVER_LANDING_PAGE_PROJECTS_PG_CONNECTIONS,
QGIS_SERVER_LOG_PROFILE,
};
};

Expand Down Expand Up @@ -124,6 +125,19 @@ Returns the maximum number of cached layers.
Returns the log level.

:return: the log level.
%End

bool logProfile();
%Docstring
Returns ``True`` if profile information has to be added to the logs, default value is ``False``.

.. note::

this flag is only effective when :py:func:`~QgsServerSettings.logLevel` returns Qgis.Info (0)

.. seealso:: :py:func:`logLevel`

.. versionadded:: 3.18
%End

QString projectFile() const;
Expand Down
275 changes: 151 additions & 124 deletions src/server/qgsserver.cpp
View file
Expand Up @@ -38,6 +38,7 @@
#include "qgsserverapicontext.h"
#include "qgsserverparameters.h"
#include "qgsapplication.h"
#include "qgsruntimeprofiler.h"

#include <QDomDocument>
#include <QNetworkDiskCache>
Expand All @@ -49,7 +50,6 @@
#include <cstdlib>



// Server status static initializers.
// Default values are for C++, SIP bindings will override their
// options in in init()
Expand Down Expand Up @@ -296,174 +296,201 @@ void QgsServer::putenv( const QString &var, const QString &val )

void QgsServer::handleRequest( QgsServerRequest &request, QgsServerResponse &response, const QgsProject *project )
{
Qgis::MessageLevel logLevel = QgsServerLogger::instance()->logLevel();
QElapsedTimer time; //used for measuring request time if loglevel < 1

qApp->processEvents();

if ( logLevel == Qgis::Info )
const Qgis::MessageLevel logLevel = QgsServerLogger::instance()->logLevel();
{
time.start();
}

response.clear();
QgsScopedRuntimeProfile profiler { QStringLiteral( "handleRequest" ), QStringLiteral( "server" ) };

// Pass the filters to the requestHandler, this is needed for the following reasons:
// Allow server request to call sendResponse plugin hook if enabled
QgsFilterResponseDecorator responseDecorator( sServerInterface->filters(), response );
qApp->processEvents();

//Request handler
QgsRequestHandler requestHandler( request, response );
response.clear();

try
{
// TODO: split parse input into plain parse and processing from specific services
requestHandler.parseInput();
}
catch ( QgsMapServiceException &e )
{
QgsMessageLog::logMessage( "Parse input exception: " + e.message(), QStringLiteral( "Server" ), Qgis::Critical );
requestHandler.setServiceException( e );
}
// Pass the filters to the requestHandler, this is needed for the following reasons:
// Allow server request to call sendResponse plugin hook if enabled
QgsFilterResponseDecorator responseDecorator( sServerInterface->filters(), response );

// Set the request handler into the interface for plugins to manipulate it
sServerInterface->setRequestHandler( &requestHandler );
//Request handler
QgsRequestHandler requestHandler( request, response );

// Initialize configfilepath so that is is available
// before calling plugin methods
// Note that plugins may still change that value using
// setConfigFilePath() interface method
if ( ! project )
{
QString configFilePath = configPath( *sConfigFilePath, request.serverParameters().map() );
sServerInterface->setConfigFilePath( configFilePath );
}
else
{
sServerInterface->setConfigFilePath( project->fileName() );
}
try
{
// TODO: split parse input into plain parse and processing from specific services
requestHandler.parseInput();
}
catch ( QgsMapServiceException &e )
{
QgsMessageLog::logMessage( "Parse input exception: " + e.message(), QStringLiteral( "Server" ), Qgis::Critical );
requestHandler.setServiceException( e );
}

// Call requestReady() method (if enabled)
// This may also throw exceptions if there are errors in python plugins code
try
{
responseDecorator.start();
}
catch ( QgsException &ex )
{
// Internal server error
response.sendError( 500, QStringLiteral( "Internal Server Error" ) );
QgsMessageLog::logMessage( ex.what(), QStringLiteral( "Server" ), Qgis::Critical );
}
// Set the request handler into the interface for plugins to manipulate it
sServerInterface->setRequestHandler( &requestHandler );

// Plugins may have set exceptions
if ( !requestHandler.exceptionRaised() )
{
// Initialize configfilepath so that is is available
// before calling plugin methods
// Note that plugins may still change that value using
// setConfigFilePath() interface method
if ( ! project )
{
QString configFilePath = configPath( *sConfigFilePath, request.serverParameters().map() );
sServerInterface->setConfigFilePath( configFilePath );
}
else
{
sServerInterface->setConfigFilePath( project->fileName() );
}

// Call requestReady() method (if enabled)
// This may also throw exceptions if there are errors in python plugins code
try
{
const QgsServerParameters params = request.serverParameters();
printRequestParameters( params.toMap(), logLevel );
responseDecorator.start();
}
catch ( QgsException &ex )
{
// Internal server error
response.sendError( 500, QStringLiteral( "Internal Server Error" ) );
QgsMessageLog::logMessage( ex.what(), QStringLiteral( "Server" ), Qgis::Critical );
}

// Setup project (config file path)
if ( ! project )
// Plugins may have set exceptions
if ( !requestHandler.exceptionRaised() )
{
try
{
QString configFilePath = configPath( *sConfigFilePath, params.map() );
const QgsServerParameters params = request.serverParameters();
printRequestParameters( params.toMap(), logLevel );

// load the project if needed and not empty
if ( ! configFilePath.isEmpty() )
// Setup project (config file path)
if ( ! project )
{
project = mConfigCache->project( configFilePath, sServerInterface->serverSettings() );
}
}

// Set the current project instance
QgsProject::setInstance( const_cast<QgsProject *>( project ) );

if ( project )
{
sServerInterface->setConfigFilePath( project->fileName() );
}
else
{
sServerInterface->setConfigFilePath( QString() );
}
QString configFilePath = configPath( *sConfigFilePath, params.map() );

// Note that at this point we still might not have set a valid project.
// There are APIs that work without a project (e.g. the landing page catalog API that
// lists the available projects metadata).
// load the project if needed and not empty
if ( ! configFilePath.isEmpty() )
{
project = mConfigCache->project( configFilePath, sServerInterface->serverSettings() );
}
}

// Dispatcher: if SERVICE is set, we assume a OWS service, if not, let's try an API
// TODO: QGIS 4 fix the OWS services and treat them as APIs
QgsServerApi *api = nullptr;
if ( params.service().isEmpty() && ( api = sServiceRegistry->apiForRequest( request ) ) )
{
QgsServerApiContext context { api->rootPath(), &request, &responseDecorator, project, sServerInterface };
api->executeRequest( context );
}
else
{
// Set the current project instance
QgsProject::setInstance( const_cast<QgsProject *>( project ) );

// Project is mandatory for OWS at this point
if ( ! project )
if ( project )
{
throw QgsServerException( QStringLiteral( "Project file error. For OWS services: please provide a SERVICE and a MAP parameter pointing to a valid QGIS project file" ) );
sServerInterface->setConfigFilePath( project->fileName() );
}

if ( ! params.fileName().isEmpty() )
else
{
const QString value = QString( "attachment; filename=\"%1\"" ).arg( params.fileName() );
requestHandler.setResponseHeader( QStringLiteral( "Content-Disposition" ), value );
sServerInterface->setConfigFilePath( QString() );
}

// Lookup for service
QgsService *service = sServiceRegistry->getService( params.service(), params.version() );
if ( service )
// Note that at this point we still might not have set a valid project.
// There are APIs that work without a project (e.g. the landing page catalog API that
// lists the available projects metadata).

// Dispatcher: if SERVICE is set, we assume a OWS service, if not, let's try an API
// TODO: QGIS 4 fix the OWS services and treat them as APIs
QgsServerApi *api = nullptr;
if ( params.service().isEmpty() && ( api = sServiceRegistry->apiForRequest( request ) ) )
{
service->executeRequest( request, responseDecorator, project );
QgsServerApiContext context { api->rootPath(), &request, &responseDecorator, project, sServerInterface };
api->executeRequest( context );
}
else
{
throw QgsOgcServiceException( QStringLiteral( "Service configuration error" ),
QStringLiteral( "Service unknown or unsupported. Current supported services (case-sensitive): WMS WFS WCS WMTS SampleService, or use a WFS3 (OGC API Features) endpoint" ) );

// Project is mandatory for OWS at this point
if ( ! project )
{
throw QgsServerException( QStringLiteral( "Project file error. For OWS services: please provide a SERVICE and a MAP parameter pointing to a valid QGIS project file" ) );
}

if ( ! params.fileName().isEmpty() )
{
const QString value = QString( "attachment; filename=\"%1\"" ).arg( params.fileName() );
requestHandler.setResponseHeader( QStringLiteral( "Content-Disposition" ), value );
}

// Lookup for service
QgsService *service = sServiceRegistry->getService( params.service(), params.version() );
if ( service )
{
service->executeRequest( request, responseDecorator, project );
}
else
{
throw QgsOgcServiceException( QStringLiteral( "Service configuration error" ),
QStringLiteral( "Service unknown or unsupported. Current supported services (case-sensitive): WMS WFS WCS WMTS SampleService, or use a WFS3 (OGC API Features) endpoint" ) );
}
}
}
catch ( QgsServerException &ex )
{
responseDecorator.write( ex );
QString format;
QgsMessageLog::logMessage( ex.formatResponse( format ), QStringLiteral( "Server" ), Qgis::Warning );
}
catch ( QgsException &ex )
{
// Internal server error
response.sendError( 500, QStringLiteral( "Internal Server Error" ) );
QgsMessageLog::logMessage( ex.what(), QStringLiteral( "Server" ), Qgis::Critical );
}
}
catch ( QgsServerException &ex )

// Terminate the response
// This may also throw exceptions if there are errors in python plugins code
try
{
responseDecorator.write( ex );
QString format;
QgsMessageLog::logMessage( ex.formatResponse( format ), QStringLiteral( "Server" ), Qgis::Warning );
responseDecorator.finish();
}
catch ( QgsException &ex )
{
// Internal server error
response.sendError( 500, QStringLiteral( "Internal Server Error" ) );
QgsMessageLog::logMessage( ex.what(), QStringLiteral( "Server" ), Qgis::Critical );
}
}

// Terminate the response
// This may also throw exceptions if there are errors in python plugins code
try
{
responseDecorator.finish();
// We are done using requestHandler in plugins, make sure we don't access
// to a deleted request handler from Python bindings
sServerInterface->clearRequestHandler();
}
catch ( QgsException &ex )

if ( logLevel == Qgis::Info )
{
// Internal server error
response.sendError( 500, QStringLiteral( "Internal Server Error" ) );
QgsMessageLog::logMessage( ex.what(), QStringLiteral( "Server" ), Qgis::Critical );
}
QgsMessageLog::logMessage( "Request finished in " + QString::number( QgsApplication::profiler()->profileTime( QStringLiteral( "handleRequest" ), QStringLiteral( "server" ) ) * 1000.0 ) + " ms", QStringLiteral( "Server" ), Qgis::Info );
if ( sSettings->logProfile() )
{
std::function <void( const QModelIndex &, int )> profileFormatter;
profileFormatter = [ &profileFormatter ]( const QModelIndex & idx, int level )
{
QgsMessageLog::logMessage( QStringLiteral( "Profile: %1%2, %3 : %4 ms" )
.arg( level > 0 ? QString().fill( '-', level ) + ' ' : QString() )
.arg( QgsApplication::profiler()->data( idx, QgsRuntimeProfilerNode::Roles::Group ).toString() )
.arg( QgsApplication::profiler()->data( idx, QgsRuntimeProfilerNode::Roles::Name ).toString() )
.arg( QString::number( QgsApplication::profiler()->data( idx, QgsRuntimeProfilerNode::Roles::Elapsed ).toDouble() * 1000.0 ) ), QStringLiteral( "Server" ), Qgis::Info );

for ( int subRow = 0; subRow < QgsApplication::profiler()->rowCount( idx ); subRow++ )
{
const auto subIdx { QgsApplication::profiler()->index( subRow, 0, idx ) };
profileFormatter( subIdx, level + 1 );
}

// We are done using requestHandler in plugins, make sure we don't access
// to a deleted request handler from Python bindings
sServerInterface->clearRequestHandler();
};

if ( logLevel == Qgis::Info )
{
QgsMessageLog::logMessage( "Request finished in " + QString::number( time.elapsed() ) + " ms", QStringLiteral( "Server" ), Qgis::Info );
for ( int row = 0; row < QgsApplication::profiler()->rowCount( ); row++ )
{
const auto idx { QgsApplication::profiler()->index( row, 0 ) };
profileFormatter( idx, 0 );
}
}
}


// Clear the profiler server section after each request
QgsApplication::profiler()->clear( QStringLiteral( "server" ) );

}


Expand Down
18 changes: 18 additions & 0 deletions src/server/qgsserversettings.cpp
View file
Expand Up @@ -265,6 +265,19 @@ void QgsServerSettings::initSettings()
};

mSettings[ sProjectsPgConnections.envVar ] = sProjectsPgConnections;

// log profile
const Setting sLogProfile = { QgsServerSettingsEnv::QGIS_SERVER_LOG_PROFILE,
QgsServerSettingsEnv::DEFAULT_VALUE,
QStringLiteral( "Add detailed profile information to the logs, only effective when QGIS_SERVER_LOG_LEVEL=0" ),
QStringLiteral( "/qgis/server_log_profile" ),
QVariant::Bool,
QVariant( false ),
QVariant()
};

mSettings[ sLogProfile.envVar ] = sLogProfile;

}

void QgsServerSettings::load()
Expand Down Expand Up @@ -513,3 +526,8 @@ bool QgsServerSettings::getPrintDisabled() const
{
return value( QgsServerSettingsEnv::QGIS_SERVER_DISABLE_GETPRINT ).toBool();
}

bool QgsServerSettings::logProfile()
{
return value( QgsServerSettingsEnv::QGIS_SERVER_LOG_PROFILE, false ).toBool();
}

0 comments on commit 6d2be40

Please sign in to comment.