{"id":43157,"date":"2026-02-25T21:06:48","date_gmt":"2026-02-25T20:06:48","guid":{"rendered":"https:\/\/www.dbi-services.com\/blog\/?p=43157"},"modified":"2026-02-25T21:06:50","modified_gmt":"2026-02-25T20:06:50","slug":"dctm-detect-and-analyze-slow-sql-queries","status":"publish","type":"post","link":"https:\/\/www.dbi-services.com\/blog\/dctm-detect-and-analyze-slow-sql-queries\/","title":{"rendered":"Dctm – Detect and analyze slow SQL queries"},"content":{"rendered":"\n

Documentum is a powerful but also complex software. Therefore, debugging performance issues often comes down to being able to implement and review various traces. In this blog, I will talk about how you can detect and analyze slow SQL queries from a Documentum Server. Several years ago, I wrote a blog post about DFC traces<\/a>. It included the setup and investigation process, using the EMC Python\/AWK parser scripts as a base. In addition, I also wrote another one about Tomcat slow\/stuck threads<\/a>. With these two posts, you could already cover the Documentum DFC clients (like JMS Apps, DA, D2, xPlore, etc.).<\/p>\n\n\n\n

As you might imagine, SQL traces in Documentum can be quite large. A lot of queries are sent to the Database to retrieve, insert or update information. Things like document metadata, users, permissions, audittrail entries, document creation, etc. It is less intensive than DFC or SSL\/Network traces, because those write dozens of lines for each and every action. On the other hand, SQL traces limit themselves to the query being executed, the execution time, and potentially some commits.<\/p>\n\n\n\n

A customer recently provided me a Repository log file with SQL traces related to a problematic action in DA. I was expecting maybe a 10 or 20-minute log file at most. But what I received was a 4-hour log file, because the action took that long to complete in DA. I thought this would be a good use case to share in a blog, to explain how you can quickly extract interesting details from such SQL traces.<\/p>\n\n\n\n

1. Defining variables<\/h2>\n\n\n\n

As often, I find it easier for both you and me to use predefined variables. This allows you to just change these details and, for the rest of the blog, simply copy\/paste the exact same queries without having to wonder whether they will work.<\/p>\n\n\n\n

I’m using my Mac and I have a folder which contains the Repository log file:<\/p>\n\n\n

\nmac:~$ ls\ndbi01.log\nmac:~$\nmac:~$ # Variables definition\nmac:~$ source_repo_log_file="dbi01.log"\nmac:~$ query_times="query_times.log"\nmac:~$ extracted_session_log_file="extracted_session_log_file.log"\n<\/pre><\/div>\n\n\n
2. Extracting the SQL execution times<\/h2>\n\n\n\n
Once done, let’s proceed directly with extracting the SQL execution times. The durations will be sorted to easily understand whether there is a problem with some queries. In the initial log file, there are more than a hundred thousand SQL queries executed. Out of these, I selected only the 47 slowest “EXEC<\/strong><\/em>” entries below. That is not an arbitrary number; I initially retrieved the last 100 lines, but most of them were less than 0.1s. Therefore, I reduced that number to only execution times that might be interesting to investigate.<\/p>\n\n\n\n
In the first command, I am selecting all “EXEC<\/em><\/strong>“, which will include the base “EXEC<\/em><\/strong>” but also other types like “EXECBATCH<\/em><\/strong>“, if any. There are also some “FETCH<\/em><\/strong>” entries in the SQL traces, but I will ignore these in this blog. The second and third commands simply show what was extracted:<\/p>\n\n\n
\nmac:~$ ### Extracting all "EXEC" times from the Repo log\nmac:~$ ### keeping the 47 slowest (>0.5s in this case)\nmac:~$ grep "EXEC" ${source_repo_log_file} | \\\n         awk '{print $7}' | \\\n         sort --version-sort | \\\n         tail -47 > ${query_times}\nmac:~$\nmac:~$ wc -l ${query_times}\n    47 query_times.log\nmac:~$\nmac:~$\nmac:~$ ### Displaying the outcome sorted by asc time\nmac:~$ cat ${query_times}\n0.5566090000\n1.0761300000\n9.9041350000\n11.2433810000\n14.6858060000\n...\n786.4434090000\n961.8524350000\n1028.2339260000\n1500.6862730000\n1970.6185150000\nmac:~$\n<\/pre><\/div>\n\n\n
The above command can be useful if you only want to extract the execution time (7th column). But most of the time, what is useful is the full line. It will display the date<\/em><\/strong> (1st column), of course as well as the OS PID<\/strong><\/em> (2nd column) that is executing this query, which can be useful in some cases. But most importantly, it will display the Session ID<\/strong><\/em> (3rd column) linked to the request. For that purpose, you can slightly modify the first command from above, to extract the full line for all “EXEC<\/strong><\/em>” and sort based on the 7th column:<\/p>\n\n\n
\nmac:~$ ### Extracting all "EXEC" complete lines from the Repo log\nmac:~$ ### keeping the 47 slowest (>0.5s in this case)\nmac:~$ grep "EXEC" ${source_repo_log_file} | \\\n         sort -k 7 --version-sort | \\\n         tail -47\n2025-12-19T12:25:33.056 102[102] 0112345682105da7 [SQL] 0 EXEC 0.5566090000\n2025-12-19T11:09:40.772 104[104] 0112345682105d65 [SQL] 0 EXEC 1.0761300000\n2025-12-19T12:01:28.042 110[110] 0112345682105d9b [SQL] 0 EXEC 9.9041350000\n2025-12-19T12:01:13.943 105[105] 01123456821058fb [SQL] 0 EXEC 11.2433810000\n2025-12-19T11:59:16.078 105[105] 01123456821058fb [SQL] 0 EXEC 14.6858060000\n...\n2025-12-19T11:03:02.001 105[105] 01123456821058fb [SQL] 0 EXEC 786.4434090000\n2025-12-19T09:59:20.090 105[105] 01123456821058fb [SQL] 0 EXEC 961.8524350000\n2025-12-19T11:59:01.360 105[105] 01123456821058fb [SQL] 0 EXEC 1028.2339260000\n2025-12-19T10:49:55.553 105[105] 01123456821058fb [SQL] 0 EXEC 1500.6862730000\n2025-12-19T09:29:55.637 105[105] 01123456821058fb [SQL] 0 EXEC 1970.6185150000\nmac:~$\n<\/pre><\/div>\n\n\n
Another way to do (almost) the same thing is based on the previously exported execution times. If you loop over them with a certain command, you can retrieve the same lines again. The only difference is that this second method will be significantly slower (since it parses the log file for each execution time instead of only once as in the previous command) and slightly less accurate in some edge cases. Technically, if you have two lines with the exact same execution time, you would not get only 2 results, but 2 x 2 results (so there would be duplicates). In my case, I do not have duplicate execution times, so it produces 100% the same outcome:<\/p>\n\n\n
\nmac:~$ ### Extracting all "EXEC" complete lines from the Repo log\nmac:~$ ### based on previously extracted execution time\nmac:~$ while read line; do \\\n         grep "EXEC.*[[:space:]]\\+${line}$" ${source_repo_log_file}; \\\n       done < <(cat ${query_times})\n2025-12-19T12:25:33.056 102[102] 0112345682105da7 [SQL] 0 EXEC 0.5566090000\n2025-12-19T11:09:40.772 104[104] 0112345682105d65 [SQL] 0 EXEC 1.0761300000\n2025-12-19T12:01:28.042 110[110] 0112345682105d9b [SQL] 0 EXEC 9.9041350000\n2025-12-19T12:01:13.943 105[105] 01123456821058fb [SQL] 0 EXEC 11.2433810000\n2025-12-19T11:59:16.078 105[105] 01123456821058fb [SQL] 0 EXEC 14.6858060000\n...\n2025-12-19T11:03:02.001 105[105] 01123456821058fb [SQL] 0 EXEC 786.4434090000\n2025-12-19T09:59:20.090 105[105] 01123456821058fb [SQL] 0 EXEC 961.8524350000\n2025-12-19T11:59:01.360 105[105] 01123456821058fb [SQL] 0 EXEC 1028.2339260000\n2025-12-19T10:49:55.553 105[105] 01123456821058fb [SQL] 0 EXEC 1500.6862730000\n2025-12-19T09:29:55.637 105[105] 01123456821058fb [SQL] 0 EXEC 1970.6185150000\nmac:~$\n<\/pre><\/div>\n\n\n
3. How long is really spent on queries?<\/h2>\n\n\n\n
Based on the above results, the first thing that stood out was that 44<\/strong><\/em> of the slowest queries appeared to be linked to the same Session ID<\/strong><\/em>. Therefore, except for the first 3 rows (0.5s, 1s, and 9.9s), all other queries came from a single source. This clearly indicates that the problematic action in DA is associated with that Session ID, and it is therefore what I need to investigate further. The next step was to extract all logs related to that Session ID:<\/p>\n\n\n
\nmac:~$ ### Extracting logs related to the specific session ID\nmac:~$ session_id="01123456821058fb"\nmac:~$ grep "${session_id}" ${source_repo_log_file} \\\n         > ${extracted_session_log_file}\nmac:~$\nmac:~$ wc -l ${extracted_session_log_file}\n    765 extracted_session_log_file.log\nmac:~$\n<\/pre><\/div>\n\n\n
Compared to the size of the log file (a few hundred thousand lines), there are only 765 lines related to that Session ID. But how much time is actually spent on these few requests? For that purpose, you can compare the sum of all “EXEC<\/strong><\/em>” times for the Repository log file<\/strong><\/em> vs the Session ID log file<\/strong><\/em> vs the 44 slowest queries<\/strong><\/em>:<\/p>\n\n\n
\nmac:~$ ### Checking the SQL execution time\nmac:~$ ### for all SQL queries in the Repo log file\nmac:~$ grep "EXEC" ${source_repo_log_file} | \\\n         awk '{print $7}' | \\\n         awk '{sum += $1}\n         END {\n           h = int(sum \/ 3600)\n           m = int((sum % 3600) \/ 60)\n           s = sum % 60\n           printf "%02dh %02dm %.3fs\\n", h, m, s\n         }'\n03h 11m 50.477s\nmac:~$\nmac:~$\nmac:~$ ### Checking the SQL execution time\nmac:~$ ### related to the specific session ID\nmac:~$ grep "EXEC" ${extracted_session_log_file} | \\\n         awk '{print $7}' | \\\n         awk '{sum += $1}\n         END {\n           h = int(sum \/ 3600)\n           m = int((sum % 3600) \/ 60)\n           s = sum % 60\n           printf "%02dh %02dm %.3fs\\n", h, m, s\n         }'\n03h 09m 56.340s\nmac:~$\nmac:~$\nmac:~$ ### Checking the SQL execution time\nmac:~$ ### for the 44 slowest related to the specific session ID\nmac:~$ cat ${query_times} | \\\n         tail -44 | \\\n         awk '{sum += $1}\n         END {\n           h = int(sum \/ 3600)\n           m = int((sum % 3600) \/ 60)\n           s = sum % 60\n           printf "%02dh %02dm %.3fs\\n", h, m, s\n         }'\n03h 09m 56.015s\nmac:~$\n<\/pre><\/div>\n\n\n
The above means that inside that ~4-hour log file, the Documentum Server executed more than a hundred thousand queries for a total sum of 3h 11m 50.5s. Of course, that is not necessarily consecutive time, as some queries might be executed in parallel by different processes. Out of these 3h 11m 50s spent on Database queries, the time related to the problematic Session ID, which represents slightly less than 0.2% of the executed SQL queries, is 3h 9m 56.3s. And out of these 0.2%, the 44 slowest queries represent 3h 9m 56.0s. That means:<\/p>\n\n\n\n