SLOWSQL log message from Service Center and Slow Call from Lifetime dashboard analytics alert us of a performance problem on our application but more information is required specifically relating to database activity.
You can also use this guide to troubleshoot applications that are hanging or unresponsive and are suspected to be database related issues.
In this post, I will go over how to extract specific information from the database when dealing with these types of log information.
Before we begin, we first need to enable some platform settings. For this, we will need to install the Factory Configuration forge component.
Once installed, open it on the browser and navigate to the Platform Configurations tab.
Scroll down and find the setting Add Query Origin to Generated SQL then make sure it is ticked and save your changes.
After the changes have been saved, applications need to be published again since this feature is applied at the compilation level. SQL generated by your OutSystems application will now include a comment with the location of the SQL in your application code. This can be handy to relate the information from the database with the logs from Service Center or Lifetime Analytics dashboard.
Here are examples of what additional information will appear with the SQL statements.
/* Query.VendorScreen.Vendor_Search.Preparation.Vendor.List */
SELECT [ENVENDOR].[ID] o0, [ENVENDOR].[NAME] o1, [ENVENDOR].[TYPE] o2
FROM [OUTSYSTEMS].dbo.[OSUSR_F66_VENDOR] [VENDOR]
This can be broken down into different sections
MODULE
UI FLOW
SCREEN
QUERY
eSpace(Independent Modules)
VendorScreen
Vendor_Search
Preparation.Vendor.List
Please skip this step if you already have connectivity to the database server.
OutSystems allows you to connect in two different ways:
Connect to the database server from any IP address of your private network. You must establish this connection through VPN or AWS Transit Gateway.
Connect to the database server from a set of public static IP addresses, allowlisted on the OutSystems side.
Please skip this step if you already have user access to the database server.
For temporary or permanent database users and more information, you can follow the process described in OutSystems’ public documentation.
Create or use an existing database login and enable the following settings:
For SQL Server
VIEW DATABASE STATE
VIEW SERVER STATE
SHOWPLAN
For Oracle:
SELECT ANY DICTIONARY
Enable add query origin to SQL generated using Factory Configuration forge component
Setup connectivity to the database server
Setup database user
Service Center General log SLOWSQL message would look something like this:
Module
Message
Query.VendorScreen.Vendor_Search.Preparation.Vendor.List took 10010 ms (Database: outsystems)
Work with an OutSystems developer to identify which screen or part of the application where the SLOWSQL is being generated from.
As per example above, the Vendor web screen and fetching the list of the Vendor is the part of the application which has generated the SLOWSQL message.
From the database point of view, you can either debug the screen / application and run a trace in order to see the SQL statement being executed by the application.
The SQL statement comment can be matched with the SLOWSQL message to help identify the correct query running on the server.
For the steps below you need to have access to the OutSystems Database. Please note that this will only capture what is currently running and stored on the query cache.
To extract this information is by running queries via the database cache which we will go over them below. Please note that these queries can be executed by temporary and permanent database users.
To use the query effectively, it needs to be executed while the suspect page or process is running at the same time to capture the SQL statement sessions currently running on the server.
SQL statement is already parsed and a new column "Module_path" shows the query origin location.
SELECT top 100
CASE WHEN LEFT(LEFT(t.text,400), 3) = '/* ' THEN SUBSTRING(LEFT(t.text,400), 4, (CHARINDEX(' */',LEFT(t.text,400), 3)-3))
ELSE CASE WHEN LEFT(LEFT(t.text,400),2) = '(@' AND LEFT(t.text,400) like '(@%)/*%' THEN SUBSTRING(LEFT(t.text,400), CHARINDEX('/* ',LEFT(t.text,400))+3, CHARINDEX('*/',LEFT(t.text,400))- CHARINDEX('/* ',LEFT(t.text,400))-3) END
END as 'Module_Path',
t.[text] AS 'QueryText',
qp.query_plan AS 'QueryPlan',
CONVERT(DECIMAL(10,2), (total_worker_time+0.0)/(execution_count*1000)) AS 'CPUTime',
qs.last_logical_reads as 'IORead',
qs.last_logical_writes as 'IOWrite',
qs.total_elapsed_time/1000 as TotDuration,
qs.execution_count AS 'ExecutionCount',
last_execution_time 'ExecutionTime',
DB_NAME(t.[dbid]) AS 'DatabaseName',
cp.objtype as 'CacheType',
qs.sql_handle
FROM sys.dm_exec_query_stats AS qs WITH (NOLOCK)
CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS t
CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS qp
left JOIN sys.dm_exec_cached_plans as cp ON qs.plan_handle = cp.plan_handle
/*
-- specific text filter on sql statement
where t.text like '%VendorScreen%'
*/
SELECT DISTINCT
CASE WHEN SUBSTR(SUBSTR(v.SQL_TEXT,1, 400), 1, 3) = '/* ' THEN SUBSTR(SUBSTR(v.SQL_TEXT,1, 400), 4, (INSTR(SUBSTR(v.SQL_TEXT,1, 400), ' */', 3)-3))
ELSE CASE WHEN SUBSTR(SUBSTR(v.SQL_TEXT,1, 400), 1,2) = '(@' AND SUBSTR(v.SQL_TEXT,1, 400) like '(@%)/*%' THEN SUBSTR(SUBSTR(v.SQL_TEXT,1, 400), INSTR(SUBSTR(v.SQL_TEXT,1, 400), '/* ')+3, INSTR(SUBSTR(v.SQL_TEXT,1, 400), '*/')- INSTR(SUBSTR(v.SQL_TEXT,1, 400), '/* ')-3)
END END as module_path,
v.SQL_TEXT,
v.EXECUTIONS,
v.CPU_TIME,
v.DISK_READS,
v.DIRECT_WRITES,
v.elapsed_time,
v.SQL_ID
FROM v$sql v
WHERE to_date(v.FIRST_LOAD_TIME,'YYYY-MM-DD hh24:mi:ss')>ADD_MONTHS(trunc(sysdate,'DD'),-1) -- Query date criteria from yesterday
AND v.SQL_TEXT LIKE '%VendorScreen%'
FETCH FIRST 100 ROWS ONLY -- top 100
Another use case for this query is during an incident or outage that is currently happening. It will give you an ability to view what is currently running which is potentially blocking the processes on your application. This will enable you to collect a snapshot list of SQL statements which you can look into or cross check against the logs.
For more detailed information regarding debugging Outsystems application please read the Official Outsystems Documentation on our website.
Sometimes we find too many log warnings due to the fact that the query was not given sufficient enough time to execute. You can extend this by changing the values of the setting in the Factory Configuration. This will help in refining and reducing the amount of log error messages.
Hope you find this information useful.
Regards
-Raynino
Cool stuff @Raynino
Thanks for sharing it :)