Get In-Depth Knowledge of how your Loading Utilities perform using the Teradata DBQL Utility Log

If you are looking to have in-depth knowledge of how your load utilities (or even DSA jobs) are running in your environment or investigating their performance, the DBQLogTbl is just the beginning.

The DBQLogTbl does provide metrics for these utilities, but not as accurate and as abundant as what Teradata DBQLUtilityTbl can offer.

What is the Teradata DBQL Utility Log?

The DBQLUtilityTbl will provide a plethora of detail, including timestamps of different phases of a utility job (acquisition and application for FastLoad/MultiLoad/MLoadX utility protocols, select and export steps for the export utility) and a DSA job (dictionary-data-build-postscript phase), logical and physical io usage, CPU time…

It is interesting to have this logging for when you want to analyze how your utility jobs perform (amount of data loaded, time spent in a delay state, time spent per phase, etc…); ultimately archive these logs and be able to have a history big enough to see patterns, tendencies and decide on potential enhancements.

To start things off, you will need a particular level of logging for the user running the utilities:

BEGIN QUERY LOGGING ON SYSPROD WITH UTILITYINFO;

This logging level is quite beefy because you cannot set a CPU threshold on this particular user; you will be logging everything.

This is important to keep note of because:

• Your DBQL reports on the activity for this particular user (or in general) can potentially skyrocket (especially query counts)
• The amount of data you are storing will increase since more data is logged

The DBQLUtilityTbl is a 129-column table; the corresponding view is QryLogUtilityV.

How to use the Teradata DBQL Utility Log

Here is a sample SQL that can narrow the information down:

SELECT 

CAST (StartTime AS DATE) logdate
,USERNAME
,sessionid
,UtilityName

/*if you have querybands defined in your utility jobs, it is a good idea to extract this information*/
,GETQUERYBANDVALUE(queryband, 0, 'JobName') AS JobName
,GETQUERYBANDVALUE(queryband, 0, 'UtilityDataSize') AS UtilityDataSize    
,GETQUERYBANDVALUE(queryband, 0, 'ClientLoadSessions') AS RequestSession  /*utility jobs can define a min and max sessions in their script*/
 
, NumSesOrBuildProc AS "GrantedSession" /*if you're using tasm workload management, what is allocated is not what is requested in the tpt script, but what is defaulted in tasm (if no utilitydatasize is defined in the queryband)*/

,EXTRACT ( HOUR   FROM Phase0StartTime ) AS hh
,EXTRACT ( MINUTE FROM Phase0StartTime ) AS mm
,jobstarttime AT TIME ZONE 'Europe Central' AS StartTime
,jobendtime AT TIME ZONE 'Europe Central' AS EndTime

/*this total elapsed time includes the time it spent waiting for a utility slot (waiting in delay state)*/
,((EndTime - StartTime) HOUR(4) TO SECOND) AS TotElapsedTime

/*easier to work with this format when graphing the data into excel*/
,CAST ( ( EXTRACT ( HOUR FROM TotElapsedTime) * 3600 + EXTRACT ( MINUTE FROM TotElapsedTime) * 60 + EXTRACT ( SECOND FROM TotElapsedTime) ) AS  DEC (10,2)) AS TotElapsedTime_sec
,CAST ( ( EXTRACT ( HOUR FROM TotElapsedTime) * 3600 + EXTRACT ( MINUTE FROM TotElapsedTime) * 60 + EXTRACT ( SECOND FROM TotElapsedTime) ) / 60.00 AS  DEC (10,2)) AS TotElapsedTime_min

/*actual elapsed time*/
,CAST ( ( EXTRACT ( HOUR FROM TotElapsedTime) * 3600 + EXTRACT ( MINUTE FROM TotElapsedTime) * 60 + EXTRACT ( SECOND FROM TotElapsedTime) ) - DelayTime AS DEC (10,2)) AS ActElapsedTime_sec
,CAST ( ( EXTRACT ( HOUR FROM TotElapsedTime) * 3600 + EXTRACT ( MINUTE FROM TotElapsedTime) * 60 + EXTRACT ( SECOND FROM TotElapsedTime) ) - DelayTime  / 60.00 AS DEC (10,2)) AS ActElapsedTime_min
,CASE WHEN DelayTime IS NULL THEN 0 ELSE DelayTime END AS DelayTime

/*phase1*/
, CAST ( EXTRACT(HOUR FROM ((phase1endtime - phase1starttime) HOUR TO SECOND)) * 3600 +
EXTRACT(MINUTE FROM ((phase1endtime - phase1starttime) HOUR TO SECOND)) * 60 +
EXTRACT(SECOND FROM ((phase1endtime - phase1starttime) HOUR TO SECOND)) AS DEC (10,2)) AS Phase1ElapsedTime
,CAST ( Phase1RowCount AS INT ) 
,CAST ( Phase2RowCount AS INT ) 
,CAST ( RowsInserted AS INT )
,CAST ( (Phase1RowCount - RowsInserted)  AS INT ) AS RowsRejected

/*phase2*/
, CAST ( EXTRACT(HOUR FROM ((phase2endtime - phase2starttime) HOUR TO SECOND)) * 3600 +
EXTRACT(MINUTE FROM ((phase2endtime - phase2starttime) HOUR TO SECOND)) * 60 +
EXTRACT(SECOND FROM ((phase2endtime - phase2starttime) HOUR TO SECOND)) AS DEC (10,2)) AS Phase2ElapsedTime

/*phase3*/
, CAST ( EXTRACT(HOUR FROM ((phase3endtime - phase3starttime) HOUR TO SECOND)) * 3600 +
EXTRACT(MINUTE FROM ((phase3endtime - phase3starttime) HOUR TO SECOND)) * 60 +
EXTRACT(SECOND FROM ((phase3endtime - phase3starttime) HOUR TO SECOND)) AS DEC (10,2)) AS Phase3ElapsedTime

FROM  dbc.DBQLUtilityTbl;

Depending on your needs, add columns to the SQL.

For this next part, you may want to check out these articles by Roland regarding the Fastload and Multiload utilities:

Having a history of DBQLUtilityTbl data, the following graphs can be produced:

*Please note that this is simulated data, and it may or may not depict an accurate behavior of a system.*

Graph 1: the amount of data vs. the time it took to load from the host machine to Teradata (phase1) for a specific job EXP-J1.

We can see that the data loaded every four days is doubled, explaining the longer load times.

However, in the last few days of the month (Oct 29th to Oct 31st), the amount of data stays below 2 million rows, similar to an average day, but the load times are still very high (around 400 seconds -or- about 6 minutes).

To explain this behavior, you will first have to look at how busy the Teradata system was (it can be very busy). If nothing out of the ordinary, you will have to look at the host machine sending this data (it can be very busy CPU and io wise – which can explain slower transfer speeds). Another suspect can be a more engaged network.

Graph 2: actual runtime vs. time spent in delay state

It is the same context as the previous graph (slow load times during month-end), but this time we are looking at how long a specific job is spent waiting for a load slot (delayed state).

We observe that every four days, this job encounters some delay. This is most likely due to a higher concurrency of TPT jobs running in the system. Without going into the details, the time spent in the delay state ranges from a few seconds (Oct 4) to almost 200 seconds (a bit over 3mins) on Oct 16, 20, 24, and 28.

Graph 3: number of daily, weekly, and monthly jobs for a given time frame

It can be interesting to see how many jobs run by schedule (monthly, weekly, or daily) and by utility (fastload, multiload).

To correlate this graph with the previous analysis, we notice that on those days (Oct 16, 20, 24, and 28) where high delays were observed for that particular job (EXP-J2), more utilities were running (precisely, more daily jobs using the tpt load protocol).

These graphs show a macro view of the situation. You will need to drill down by hour (and even by the minute for more granularity).

I hope this article has brought you helpful information regarding this logging level and what you can get out of it.

Don’t hesitate to post your comments for any questions or clarifications!