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. 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. With these two posts, you could already cover the Documentum DFC clients (like JMS Apps, DA, D2, xPlore, etc.).

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.

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.

1. Defining variables

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.

I’m using my Mac and I have a folder which contains the Repository log file:

mac:~$ ls
dbi01.log
mac:~$
mac:~$ # Variables definition
mac:~$ source_repo_log_file="dbi01.log"
mac:~$ query_times="query_times.log"
mac:~$ extracted_session_log_file="extracted_session_log_file.log"

2. Extracting the SQL execution times

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” 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.

In the first command, I am selecting all “EXEC“, which will include the base “EXEC” but also other types like “EXECBATCH“, if any. There are also some “FETCH” entries in the SQL traces, but I will ignore these in this blog. The second and third commands simply show what was extracted:

mac:~$ ### Extracting all "EXEC" times from the Repo log
mac:~$ ### keeping the 47 slowest (>0.5s in this case)
mac:~$ grep "EXEC" ${source_repo_log_file} | \
         awk '{print $7}' | \
         sort --version-sort | \
         tail -47 > ${query_times}
mac:~$
mac:~$ wc -l ${query_times}
    47 query_times.log
mac:~$
mac:~$
mac:~$ ### Displaying the outcome sorted by asc time
mac:~$ cat ${query_times}
0.5566090000
1.0761300000
9.9041350000
11.2433810000
14.6858060000
...
786.4434090000
961.8524350000
1028.2339260000
1500.6862730000
1970.6185150000
mac:~$

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 (1st column), of course as well as the OS PID (2nd column) that is executing this query, which can be useful in some cases. But most importantly, it will display the Session ID (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” and sort based on the 7th column:

mac:~$ ### Extracting all "EXEC" complete lines from the Repo log
mac:~$ ### keeping the 47 slowest (>0.5s in this case)
mac:~$ grep "EXEC" ${source_repo_log_file} | \
         sort -k 7 --version-sort | \
         tail -47
2025-12-19T12:25:33.056 102[102] 0112345682105da7 [SQL] 0 EXEC 0.5566090000
2025-12-19T11:09:40.772 104[104] 0112345682105d65 [SQL] 0 EXEC 1.0761300000
2025-12-19T12:01:28.042 110[110] 0112345682105d9b [SQL] 0 EXEC 9.9041350000
2025-12-19T12:01:13.943 105[105] 01123456821058fb [SQL] 0 EXEC 11.2433810000
2025-12-19T11:59:16.078 105[105] 01123456821058fb [SQL] 0 EXEC 14.6858060000
...
2025-12-19T11:03:02.001 105[105] 01123456821058fb [SQL] 0 EXEC 786.4434090000
2025-12-19T09:59:20.090 105[105] 01123456821058fb [SQL] 0 EXEC 961.8524350000
2025-12-19T11:59:01.360 105[105] 01123456821058fb [SQL] 0 EXEC 1028.2339260000
2025-12-19T10:49:55.553 105[105] 01123456821058fb [SQL] 0 EXEC 1500.6862730000
2025-12-19T09:29:55.637 105[105] 01123456821058fb [SQL] 0 EXEC 1970.6185150000
mac:~$

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:

mac:~$ ### Extracting all "EXEC" complete lines from the Repo log
mac:~$ ### based on previously extracted execution time
mac:~$ while read line; do \
         grep "EXEC.*[[:space:]]\+${line}$" ${source_repo_log_file}; \
       done < <(cat ${query_times})
2025-12-19T12:25:33.056 102[102] 0112345682105da7 [SQL] 0 EXEC 0.5566090000
2025-12-19T11:09:40.772 104[104] 0112345682105d65 [SQL] 0 EXEC 1.0761300000
2025-12-19T12:01:28.042 110[110] 0112345682105d9b [SQL] 0 EXEC 9.9041350000
2025-12-19T12:01:13.943 105[105] 01123456821058fb [SQL] 0 EXEC 11.2433810000
2025-12-19T11:59:16.078 105[105] 01123456821058fb [SQL] 0 EXEC 14.6858060000
...
2025-12-19T11:03:02.001 105[105] 01123456821058fb [SQL] 0 EXEC 786.4434090000
2025-12-19T09:59:20.090 105[105] 01123456821058fb [SQL] 0 EXEC 961.8524350000
2025-12-19T11:59:01.360 105[105] 01123456821058fb [SQL] 0 EXEC 1028.2339260000
2025-12-19T10:49:55.553 105[105] 01123456821058fb [SQL] 0 EXEC 1500.6862730000
2025-12-19T09:29:55.637 105[105] 01123456821058fb [SQL] 0 EXEC 1970.6185150000
mac:~$

3. How long is really spent on queries?

Based on the above results, the first thing that stood out was that 44 of the slowest queries appeared to be linked to the same Session ID. 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:

mac:~$ ### Extracting logs related to the specific session ID
mac:~$ session_id="01123456821058fb"
mac:~$ grep "${session_id}" ${source_repo_log_file} \
         > ${extracted_session_log_file}
mac:~$
mac:~$ wc -l ${extracted_session_log_file}
    765 extracted_session_log_file.log
mac:~$

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” times for the Repository log file vs the Session ID log file vs the 44 slowest queries:

mac:~$ ### Checking the SQL execution time
mac:~$ ### for all SQL queries in the Repo log file
mac:~$ grep "EXEC" ${source_repo_log_file} | \
         awk '{print $7}' | \
         awk '{sum += $1}
         END {
           h = int(sum / 3600)
           m = int((sum % 3600) / 60)
           s = sum % 60
           printf "%02dh %02dm %.3fs\n", h, m, s
         }'
03h 11m 50.477s
mac:~$
mac:~$
mac:~$ ### Checking the SQL execution time
mac:~$ ### related to the specific session ID
mac:~$ grep "EXEC" ${extracted_session_log_file} | \
         awk '{print $7}' | \
         awk '{sum += $1}
         END {
           h = int(sum / 3600)
           m = int((sum % 3600) / 60)
           s = sum % 60
           printf "%02dh %02dm %.3fs\n", h, m, s
         }'
03h 09m 56.340s
mac:~$
mac:~$
mac:~$ ### Checking the SQL execution time
mac:~$ ### for the 44 slowest related to the specific session ID
mac:~$ cat ${query_times} | \
         tail -44 | \
         awk '{sum += $1}
         END {
           h = int(sum / 3600)
           m = int((sum % 3600) / 60)
           s = sum % 60
           printf "%02dh %02dm %.3fs\n", h, m, s
         }'
03h 09m 56.015s
mac:~$

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:

  • 100% SQL queries >> 3h 11m 50.5s = 11’510.5s
    • 99.8% SQL queries >> 1m 54s = 114s
    • 0.2% SQL queries >> 3h 9m 56.3s = 11’396.3s
      • 0.165% SQL queries >> 0.3s
      • 0.035% SQL queries >> 3h 9m 56.0s = 11’396.0s

In other words, 0.035% of the SQL queries executed represent 99% of the time spent on the Database.

4. Finding the responsible queries

Now that we have clear evidence related to the execution times, the next step is to retrieve the associated queries that are the source of the performance issue. Below, I am simply retrieving the line containing the execution time, as well as the previous line, which is supposed to contain the triggered query.

This is normally safe because I am checking only the extracted Session ID logs. Since a session is most likely sequential, it is relatively straightforward to retrieve the query responsible for the long execution times. There might be parallel executions for some batch processing, but I am not sure whether that would use the same session ID or a dedicated one per batch/thread.

If you have long running SQLs for multiple sessions, then you might want/need to take care of that and do the check session by session.

If you try to use the full Repository log instead, you will probably end up with an incorrect N-1 line. In that case, you would need a more complex parsing mechanism based on the Session ID. You can check the blog I mentioned earlier for an example of DFC trace parsing using awk. For this blog, I am keeping it simple, but I might create another post with a more advanced parser that performs everything automatically. So, let’s extract the SQL queries related to the 44 slowest execution times:

mac:~$ ### Extracting all 44 slowest queries
mac:~$ ### from the specific session ID log file
mac:~$ while read line; do \
         grep -B1 "${line}" ${extracted_session_log_file}; \
       done < <(cat ${query_times})
2025-12-19T12:01:02.700 105[105] 01123456821058fb [SQL] 0 select all dm_audittrail.session_id, dm_audittrail.user_name, dm_audittrail.event_name, dm_audittrail.event_description, dm_audittrail.time_stamp, dm_audittrail.object_type from dm_audittrail_sp  dm_audittrail where (dm_audittrail.event_description like '[TRANSACTION_TRACKING_EVENTS]%')
2025-12-19T12:01:13.943 105[105] 01123456821058fb [SQL] 0 EXEC 11.2433810000
2025-12-19T11:59:01.393 105[105] 01123456821058fb [SQL] 0 select all dm_audittrail.user_name, dm_audittrail.session_id, dm_audittrail.event_name, dm_audittrail.string_1, dm_audittrail.string_2, dm_audittrail.string_3, dm_audittrail.string_4, dm_audittrail.time_stamp from dm_audittrail_sp  dm_audittrail where (dm_audittrail.event_name in ('dm_connect', 'dm_logon_failure'))
2025-12-19T11:59:16.078 105[105] 01123456821058fb [SQL] 0 EXEC 14.6858060000
2025-12-19T12:00:09.566 105[105] 01123456821058fb [SQL] 0 select all dm_audittrail.session_id, dm_audittrail.user_name, dm_audittrail.time_stamp from dm_audittrail_sp  dm_audittrail where ((dm_audittrail.event_name='dm_connect') and dm_audittrail.user_name in (select all dm_repeating.users_names from dm_group_sp  dm_group, dm_group_rp dm_repeating where ((dm_group.group_name='dm_occasional_user_role')) and dm_repeating.r_object_id=dm_group.r_object_id )) order by dm_audittrail.r_object_id desc
2025-12-19T12:01:02.696 105[105] 01123456821058fb [SQL] 0 EXEC 53.1301340000
2025-12-19T11:59:16.083 105[105] 01123456821058fb [SQL] 0 select all dm_audittrail.session_id, dm_audittrail.user_name, dm_audittrail.time_stamp from dm_audittrail_sp  dm_audittrail where ((dm_audittrail.event_name='dm_disconnect') and dm_audittrail.user_name in (select all dm_repeating.users_names from dm_group_sp  dm_group, dm_group_rp dm_repeating where ((dm_group.group_name='dm_occasional_user_role')) and dm_repeating.r_object_id=dm_group.r_object_id )) order by dm_audittrail.r_object_id desc
2025-12-19T12:00:09.563 105[105] 01123456821058fb [SQL] 0 EXEC 53.4798570000
2025-12-19T11:13:44.269 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000153')) ))
2025-12-19T11:15:01.033 105[105] 01123456821058fb [SQL] 0 EXEC 76.7641310000
2025-12-19T11:18:59.434 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000154')) ))
2025-12-19T11:20:16.256 105[105] 01123456821058fb [SQL] 0 EXEC 76.8221030000
2025-12-19T11:08:31.916 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000152')) ))
2025-12-19T11:09:49.809 105[105] 01123456821058fb [SQL] 0 EXEC 77.8924590000
2025-12-19T10:10:44.752 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010b')) ))
2025-12-19T10:12:03.103 105[105] 01123456821058fb [SQL] 0 EXEC 78.3507420000
2025-12-19T11:03:02.009 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000151')) ))
2025-12-19T11:04:20.605 105[105] 01123456821058fb [SQL] 0 EXEC 78.5954180000
2025-12-19T11:36:05.711 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001b4')) ))
2025-12-19T11:37:27.600 105[105] 01123456821058fb [SQL] 0 EXEC 81.8885210000
2025-12-19T11:24:26.958 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000155')) ))
2025-12-19T11:25:49.718 105[105] 01123456821058fb [SQL] 0 EXEC 82.7602900000
2025-12-19T11:30:19.107 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001aa')) ))
2025-12-19T11:31:44.148 105[105] 01123456821058fb [SQL] 0 EXEC 85.0403360000
2025-12-19T09:32:33.679 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000102')) ))
2025-12-19T09:34:06.477 105[105] 01123456821058fb [SQL] 0 EXEC 92.7986000000
2025-12-19T10:03:31.061 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010a')) ))
2025-12-19T10:05:07.569 105[105] 01123456821058fb [SQL] 0 EXEC 96.5074910000
2025-12-19T11:11:47.250 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000152') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:13:44.264 105[105] 01123456821058fb [SQL] 0 EXEC 117.0139310000
2025-12-19T11:09:49.815 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000152') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:11:47.247 105[105] 01123456821058fb [SQL] 0 EXEC 117.4327020000
2025-12-19T11:17:00.411 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000153') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:18:59.431 105[105] 01123456821058fb [SQL] 0 EXEC 119.0201020000
2025-12-19T11:15:01.040 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000153') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:17:00.406 105[105] 01123456821058fb [SQL] 0 EXEC 119.3658150000
2025-12-19T11:04:20.613 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000151') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:06:23.110 105[105] 01123456821058fb [SQL] 0 EXEC 122.4972100000
2025-12-19T11:22:23.775 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000154') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:24:26.953 105[105] 01123456821058fb [SQL] 0 EXEC 123.1771960000
2025-12-19T10:12:03.114 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010b') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T10:14:09.285 105[105] 01123456821058fb [SQL] 0 EXEC 126.1710020000
2025-12-19T10:14:09.290 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010b') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T10:16:15.546 105[105] 01123456821058fb [SQL] 0 EXEC 126.2559010000
2025-12-19T11:20:16.262 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000154') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:22:23.770 105[105] 01123456821058fb [SQL] 0 EXEC 127.5082070000
2025-12-19T11:33:56.973 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001aa') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:36:05.705 105[105] 01123456821058fb [SQL] 0 EXEC 128.7315320000
2025-12-19T11:06:23.115 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000151') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:08:31.910 105[105] 01123456821058fb [SQL] 0 EXEC 128.7948250000
2025-12-19T11:37:27.606 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001b4') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:39:39.265 105[105] 01123456821058fb [SQL] 0 EXEC 131.6585850000
2025-12-19T11:31:44.156 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001aa') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:33:56.971 105[105] 01123456821058fb [SQL] 0 EXEC 132.8144410000
2025-12-19T11:39:39.270 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='28123456800001b4') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:41:53.017 105[105] 01123456821058fb [SQL] 0 EXEC 133.7473340000
2025-12-19T11:25:49.725 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000155') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T11:28:03.796 105[105] 01123456821058fb [SQL] 0 EXEC 134.0701630000
2025-12-19T11:28:03.801 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000155') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:30:19.104 105[105] 01123456821058fb [SQL] 0 EXEC 135.3037450000
2025-12-19T09:29:55.642 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000100') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T09:32:33.673 105[105] 01123456821058fb [SQL] 0 EXEC 158.0316130000
2025-12-19T09:34:06.482 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000102') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T09:36:51.885 105[105] 01123456821058fb [SQL] 0 EXEC 165.4027790000
2025-12-19T10:07:57.988 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010a') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T10:10:44.749 105[105] 01123456821058fb [SQL] 0 EXEC 166.7611230000
2025-12-19T10:05:07.576 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='281234568000010a') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T10:07:57.984 105[105] 01123456821058fb [SQL] 0 EXEC 170.4081960000
2025-12-19T09:36:51.889 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000102') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T09:39:43.525 105[105] 01123456821058fb [SQL] 0 EXEC 171.6363780000
2025-12-19T09:39:43.530 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='6d1234568000011e')) ))
2025-12-19T09:43:18.230 105[105] 01123456821058fb [SQL] 0 EXEC 214.6996070000
2025-12-19T09:59:20.094 105[105] 01123456821058fb [SQL] 0 select all count(*) "total_file_count" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='6d1234568000011e') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T10:03:31.053 105[105] 01123456821058fb [SQL] 0 EXEC 250.9586420000
2025-12-19T08:51:17.559 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000100')) ))
2025-12-19T08:57:05.010 105[105] 01123456821058fb [SQL] 0 EXEC 347.4517930000
2025-12-19T10:16:15.551 105[105] 01123456821058fb [SQL] 0 select all dmr_content.set_time from dmr_content_sp  dmr_content where (dmr_content.set_time=(select all max(dmr_content.set_time) from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000150')) ))
2025-12-19T10:24:54.860 105[105] 01123456821058fb [SQL] 0 EXEC 519.3084910000
2025-12-19T10:49:55.557 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000150') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is null) and (dmr_content.is_archived=0))
2025-12-19T11:03:02.001 105[105] 01123456821058fb [SQL] 0 EXEC 786.4434090000
2025-12-19T09:43:18.238 105[105] 01123456821058fb [SQL] 0 select all count(*) "total_file_count" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='6d1234568000011e') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T09:59:20.090 105[105] 01123456821058fb [SQL] 0 EXEC 961.8524350000
2025-12-19T11:41:53.126 105[105] 01123456821058fb [SQL] 0 select all u.r_object_id, u.user_name, u.user_privileges, u.user_xprivileges, count(s.object_name) "document_count" from dm_user_sp  u, dm_sysobject_sp  s where ((u.user_name=s.owner_name)) and (s.i_has_folder = 1 and s.i_is_deleted = 0) group by u.user_name, u.user_privileges, u.user_xprivileges, u.r_object_id
2025-12-19T11:59:01.360 105[105] 01123456821058fb [SQL] 0 EXEC 1028.2339260000
2025-12-19T10:24:54.866 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000150') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T10:49:55.553 105[105] 01123456821058fb [SQL] 0 EXEC 1500.6862730000
2025-12-19T08:57:05.019 105[105] 01123456821058fb [SQL] 0 select all count(*) "totalsize" from dmr_content_sp  dmr_content where ((dmr_content.storage_id='2812345680000100') and  exists (select r_object_id from dmr_content_r where dmr_content.r_object_id = r_object_id and parent_id is not null) and (dmr_content.is_archived=0))
2025-12-19T09:29:55.637 105[105] 01123456821058fb [SQL] 0 EXEC 1970.6185150000
mac:~$

There are quite a few interesting things we can see above. The slowest queries (>76s) are all related to documents/contents:

  • For each dm_filestore that exists in the Repository (12 above):
    • 1 x ‘select all dmr_content.set_time from dmr_content_sp …‘
    • 2 x ‘select all count(*) “totalsize” from dmr_content_sp …‘ (objects with and without parent_id)
  • For each dm_ca_store that exists in the Repository (1 above):
    • 1 x ‘select all dmr_content.set_time from dmr_content_sp …‘
    • 2 x ‘select all count(*) “total_file_count” from dmr_content_sp …‘ (objects with and without parent_id)
  • 1 x ‘select all u.r_object_id, u.user_name, u.user_privileges, u.user_xprivileges, count(s.object_name) “document_count” from dm_user_sp u, dm_sysobject_sp s …‘

This shows that the 40 slowest queries are:

  • retrieving the set_time for all documents in a storage
  • counting the number of documents in a storage
  • retrieving all users and their associated documents

The slightly faster (but still slow) queries (11s < x < 53s) are linked to the audittrail, retrieving entries related to ‘[TRANSACTION_TRACKING_EVENTS]‘, ‘dm_connect‘, ‘dm_logon_failure‘, or ‘dm_disconnect‘ events, as well as the ‘dm_occasional_user_role‘ group.

5. Linking queries to the initial issue

The final step, once you know all the problematic/slowest requests, is either to try to improve the queries or at least find a way to avoid them. This can take various forms, such as changing the query (if it comes from custom development/configuration), improving the execution plan at the DB level, or adding indexes.

In this case, as a reminder, the issue was a problematic action in DA. A user was trying to execute the “External Transaction Activity” report. If I am not mistaken, this is a relatively new System Report available since version 23.4 and backported to earlier versions through a HotFix. However, even in 23.4, it also requires a hotfix to work properly, as the OOTB version is unusable because of some logging errors.

This report is supposed to fetch and display:

  • the list of users considered “external” (e.g. part of dm_external_users or dm_extuser_data_access groups)
  • the number of transactions performed by these external users for the selected year and split by quarter
  • the total number of transactions for all external users

Nothing in this report should require document storage queries to be executed. Even worse, these long-running SQL queries are actually triggered twice. When you access the “External Transaction Activity” report page in DA, it immediately triggers all the report queries in the background, even if you have not selected a year or clicked any button. Then, when you select a year and click “Generate” or “Export“, it re-triggers the exact same queries a second time.

In the Repository traces discussed in this blog, it was only the initial access to the form page – and it already took 4 hours. That customer would therefore likely need around 8 hours to generate and display the report. And this was not even their PROD environment, but a smaller DEV one.

That is obviously a bug (and arguably a design issue). I am currently in discussion with OpenText to find a way to fix the problem in version 23.4. Please note that in version 25.4, several improvements were made to the System Report, and it appears to have fixed this specific issue from 25.4 onwards.

This blog and trace file were just an example, but one that really happened at a customer site. I hope it provided some useful insights and that it will help you in your investigations!

Post Views: 12
Thumbnail [60x60]
by
Morgan Patou