poor TMQ peformances vs SQL

[vincent-kali]

Hi all,

I'm working with TMQ on a large repo (about 10 millions of docs) on a community 5.1.g.
When running a batch of queries using SearchService API (with transactional queryConsistency), at a regular interval the response time is beyond 3 mn (sometimes 10mn or higher!).
All other queries return almost immediately.
All queries are strictly identical, just parameters (property values) change.
We tried to run SearchService queries starting each time a new RO transactions (retryingtransactionhelper) without any positive effect.

This behavior is easily reproductible, even with no other activity on the repo (just run a batch of queries, and every 5-6 queries one is 'stuck' during minutes).
We can see the long duration SELECT query in pg_stat_activity in postgres DB.

Tests done:
- run exactly the same batch of queries directly in SQL using psql client -> performances are very good. (SQL SELECT produced by SearchService have been captured and rerun with psql script)
- write an alf webscript that connect directly in SQL (instead of using SearchService), and run exactly the same batch of queries -> performances are very good.

It means that when using SearchService, SQL queries context have something that limit in anyway the query performances...

We did the basics maintenance operations on DB (index, vacuum, analyse...), and the native SQL query performances means that the DB itself is OK.

We checked this link, but I'm still out of ideas
http://docs.alfresco.com/community/concepts/db-config-properties.html

Any advice ?
Thanks,
Vincent

[afaust]

Be careful though with how you run the captured SQL. What you have listed in your post is the "effective SQL query", i.e. with all the parameters filled in. But Alfresco actually does execute this using a prepared statement. So in order to run the SQL query in a comparative way to the web service, you need to use the proper PREPARE and EXECUTE directives, instead of just running the effective SQL.

Would it be possible for you to attach the raw spy.log file, so it is possible to see which queries take what amount of time?

[vincent-kali]

OK I'll do that using a prepared statement as alf does (but I don't see any 'prepare' statement in spy.log, maybe is this normal ? I'm not familiar with SQL prepared statement ...).

The spy.log file is available here (quite big, around 20MB).

Long queries are found at lines 48496 and 48592.

Thanks for your help....

Vincent

[afaust]

P6Spy does logical logging on the JDBC layer. You will not see the PREPARE / EXECUTE commands that using a prepared statement entails in raw SQL in the P6Spy log - that is where these two columns of statements comes in. The last column is the effective statement, and the column before is the actually used prepared statement.

So in your case you'd need to run a PREPARE + EXPLAIN ANALYZE EXECUTE + DEALLOCATE PREPARE cycle on

select
   node.id as id
from
   alf_node node
where
   node.type_qname_id <> ?
   AND node.store_id = ?
   AND
   (
      node.id IN (select aspect.node_id from alf_node_aspects aspect where aspect.qname_id IN  (  ? ) )
      AND node.id IN (select PROP.node_id from alf_node_properties PROP where (? = PROP.qname_id) AND PROP.string_value = ?)
      AND node.id IN (select PROP.node_id from alf_node_properties PROP where (? = PROP.qname_id) AND PROP.string_value = ?)
      AND node.id IN (select PROP.node_id from alf_node_properties PROP where (? = PROP.qname_id) AND PROP.string_value = ?)
      AND node.id IN (select PROP.node_id from alf_node_properties PROP where (? = PROP.qname_id) AND PROP.string_value = ?)
   )
order by
   node.audit_modified DESC‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

for the parameters: 149, 6, 260, 249, 'Mandats', 245, '1', 247, '989179', 248, 'AGA02004'

[vincent-kali]

Hi Axel,

Thanks a lot for your feedbacks.

According to PostgreSQL doc "Prepared statements only last for the duration of the current database session".

How to understand this in connection pool context ? In other words, should I execute a prepare statement only once, at the beginning of the query batch, or before each query ? (i.e does a user http connexion map to a SQL session ?).

(I'll anyway run a set of tests using prepare and post results).

Vincent

[afaust]

You can explicitly deallocate a prepared statement with the DEALLOCATE PREPARE command I mentioned. Alfresco (iBatis) will close the prepared statement after each use, which is - as far as I know - similar to deallocating it.

[vincent-kali]

When looping the query below, I can't reproduce the issue.

Should I run the full query sequence (with acl checks) with prepare/deallocate for each single query ?

Should I deallocate after every execute (does it make sense ?).

(+ dummy question: I can't format code properly in forum, any help page anywhere ?)

PREPARE queryNodes (bigint) AS
   select  node.id as id
   from alf_node node
   where
      node.type_qname_id <> $1
      AND node.store_id = $2
      AND (
         node.id IN (select aspect.node_id from alf_node_aspects aspect where aspect.qname_id IN ( $3 ) )
         AND node.id IN ( select PROP.node_id from alf_node_properties PROP where ($4 = PROP.qname_id) AND PROP.string_value = $5 ) 
         AND node.id IN ( select PROP.node_id from alf_node_properties PROP where ($6 = PROP.qname_id) AND PROP.string_value = $7 ) 
         AND node.id IN ( select PROP.node_id from alf_node_properties PROP where ($8 = PROP.qname_id) AND PROP.string_value = $9 ) 
         AND node.id IN ( select PROP.node_id from alf_node_properties PROP where ($10 = PROP.qname_id) AND PROP.string_value = $11 ) 
      ) 
   order by node.audit_modified DESC
;

EXECUTE queryNodes (149, 6, 260, 249, 'Mandats', 245, '1', 247, '789616', 248, 'AG7912');
DEALLOCATE queryNodes;‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Edited by ‌ to show syntax highlighting (via expanded editor toolbar => "More" menu => "Syntax highlighter"

[afaust]

Deallocation after every execute is what Alfresco does implicitly (via the iBatis / MyBatis framework). If doing just this query does not reproduce the issue then you might really have to do the full sequence of queries, if you really want to pinpoint it to a specific constellation so you can provide more data to the PostgreSQL folks. Basically have a tool ready to parse the p6spy log and turn those statements into prepare-execute-deallocate cycles...