jcf.t_get_taskinfo() not reporting memory usage

Hi,

JChem version 5.12.4; Database = Oracle.

select * from table(jcf.t_get_taskinfo());

Does not return the memory usage or start_time while the queries are running.

Regards,

Guy

Hi Guy,

In my environment, both entries (columns) are returned. There is no memory usage column, there is an ESTIM_MEMORY_USE column instead. It holds NULL, meaning that the value is unknown. There is a START_TIME column which contains the start time of the query.

(I am attaching a screen shot to demonstrate.)

Peter

Hi Peter,

I am tracking a few slow queries.

select ESTIM_MEMORY_USE, START_TIME from table(jcf.t_get_taskinfo());

I am not able to see the start_time. Is this an indication that the query is hanging?

 

Regards,

Guy

Hi Guy,

Is this JChem Cartridge installed on an Oracle RAC?

Except the JCC_SESSION_ID, are all other columns NULL for this query?

In principle, the START_DATE field is supposed to be set early at the beginning of the query and isn't supposed to be changed during the life-time of the search.

How long does it take for these queries to complete? Do they seem to never finish?

Thanks,

Peter

Hi Peter,

All of the othere fields are null.

It takes about 30 minutes for the query to complete.

If I run the same query as 3 separate jobs. All 3 show up in the task query and all 3 jobs are completed at the same time. The start_time is never filled in (just checking the task info every few minutes).

 

Regards,

Guy

Hi Peter,

All of the othere fields are null.

It takes about 30 minutes for the query to complete.

If I run the same query as 3 separate jobs. All 3 show up in the task query and all 3 jobs are completed at the same time. The start_time is never filled in (just checking the task info every few minutes).

 

Regards,

Guy

Hi Guy,

Given the very long completion times of these searches, the JChem Cartridge search operators are likely to be executed as filter functions for these queries. The task list we're looking at is meant to display those JCC operator executions which are being done in domain index scan mode. (Filter functions are typically called by Oracle many times for a top-level SQL query and each single function call typically completes very fast -- orders of magnitude faster than the entire SQL query. There is thus no point in tracking them as tasks -- and this would also incure some non-negligeable overhead.)

As there are not supposed to be any task entries for filter functions, the entry with the NULL column values might be an unrelated zombie task.

Please, could you check the execution plan of the SQL queries in question to confirm or refute my speculation above?

Thanks,

Peter

Hi Peter,

My test query is a simple jc_compare call.

-Guy

Hi Guy,

The SQL appears to have a single JC_COMPARE condition, indeed, but the execution plan shows a second condition: ACTIVE=1 . How can this be explained?

Thanks

Peter

Hi Peter,

Here is a simpler query. It is still a slow query -- 15 - 45 minutes to complete.

JChem cartridge version = 5.12.4

 

Thanks

Guy

Hi Guy,

300% variation in completion time seems pretty significant... Is this an otherwise idle system or is there concurrent load on it (from other users, for example)?

It could be useful if logging statistics on core JCB-search could be turned on. You can do this by removing the comment sign (#) from the beginning of the following line in jchem/cartridge/conf/logging.properties:

# chemaxon.jchem.db.JChemSearch.stats.level = FINE

so as to make it read:

chemaxon.jchem.db.JChemSearch.stats.level = FINE

. The statistics can be retrieved in the log files in jchem/cartridge/logs. (Screening time, total search time, screened counts are logged for each individual search. Obviously, the most useful the statistics are if we are able to match them with end-to-end times of individual JCC searches.)

Thanks,

Peter

Hi Peter,

The large variation in time is due to the number of queries being run at the same time. 

We temporarily increased the number of CPUs from 4 to 8.

My original 12-15 minute query is now running ~6 minutes with 8 threads.

In the log below. 

I ran the first query in isolation to get the 6 minute timing.

In the next 3 logs -- I ran the same query 15 times. All of the queries appear to block each other.

The 15 queries all return after ~107 minutes of processing.

 

Thanks

Guy

 

[Thread-4/14]: 2013-06-02 22:06:14.728 chemaxon.jchem.db.JChemSearch printSearchInfo

FINE: 

Sun Jun 02 22:02:36 PDT 2013

Search mode: FULL

Structure table: COMPOUND.CMPD_STRUCTURE_JC_IDX_JCX

Query: [#6]-[#7](-[#6]-[#6]-1=[#7]-[#6]-2=[#6](-[#7])-[#7]=[#6](-[#7])-[#7]=[#6]-2-[#7]=[#6]-1)-[#6]-1=[#6]-[#6]=[#6](-[#6]=[#6]-1)-[#6](=O)-[#7]-[#6](-[#6]-[#6]-[#6](-[#8])=O)-[#6](-[#8])=O |c:5,11,14,19,21,t:3,8,17|

Total screened: 6

Unique screened: 6

Hits: 6

Cache loading: 94048 ms

Cache size (this table / total): 155.26 / 155.26 MBytes

Instrumented cache size: 186.96 MBytes

Total time: 368837 ms  Screening: 50700 ms

Processing threads: 8

Current / peak / maximum searches per minute: 1 / 1 / Unlimited

 

[Thread-16/15]: 2013-06-03 00:08:01.072 chemaxon.jchem.db.JChemSearch printSearchInfo

FINE: 

Sun Jun 02 22:35:30 PDT 2013

Search mode: FULL

Structure table: COMPOUND.CMPD_STRUCTURE_JC_IDX_JCX

Query: [#6]-[#7](-[#6]-[#6]-1=[#7]-[#6]-2=[#6](-[#7])-[#7]=[#6](-[#7])-[#7]=[#6]-2-[#7]=[#6]-1)-[#6]-1=[#6]-[#6]=[#6](-[#6]=[#6]-1)-[#6](=O)-[#7]-[#6](-[#6]-[#6]-[#6](-[#8])=O)-[#6](-[#8])=O |c:5,11,14,19,21,t:3,8,17|

Total screened: 6

Unique screened: 6

Hits: 6

Total time: 6469067 ms  Screening: 857333 ms

Processing threads: 8

Current / peak / maximum searches per minute: 1 / 1 / Unlimited

 

[Thread-13/16]: 2013-06-03 00:08:03.057 chemaxon.jchem.db.JChemSearch printSearchInfo

FINE: 

Sun Jun 02 22:40:33 PDT 2013

Search mode: FULL

Structure table: COMPOUND.CMPD_STRUCTURE_JC_IDX_JCX

Query: [#6]-[#7](-[#6]-[#6]-1=[#7]-[#6]-2=[#6](-[#7])-[#7]=[#6](-[#7])-[#7]=[#6]-2-[#7]=[#6]-1)-[#6]-1=[#6]-[#6]=[#6](-[#6]=[#6]-1)-[#6](=O)-[#7]-[#6](-[#6]-[#6]-[#6](-[#8])=O)-[#6](-[#8])=O |c:5,11,14,19,21,t:3,8,17|

Total screened: 6

Unique screened: 6

Hits: 6

Total time: 6471117 ms  Screening: 893883 ms

Processing threads: 8

Current / peak / maximum searches per minute: 1 / 1 / Unlimited

 

[Thread-7/17]: 2013-06-03 00:08:05.893 chemaxon.jchem.db.JChemSearch printSearchInfo

FINE: 

Sun Jun 02 22:55:51 PDT 2013

Search mode: FULL

Structure table: COMPOUND.CMPD_STRUCTURE_JC_IDX_JCX

Query: [#6]-[#7](-[#6]-[#6]-1=[#7]-[#6]-2=[#6](-[#7])-[#7]=[#6](-[#7])-[#7]=[#6]-2-[#7]=[#6]-1)-[#6]-1=[#6]-[#6]=[#6](-[#6]=[#6]-1)-[#6](=O)-[#7]-[#6](-[#6]-[#6]-[#6](-[#8])=O)-[#6](-[#8])=O |c:5,11,14,19,21,t:3,8,17|

Total screened: 6

Unique screened: 6

Hits: 6

Total time: 6474110 ms  Screening: 850921 ms

Processing threads: 8

Current / peak / maximum searches per minute: 1 / 1 / Unlimited

Hi Guy,

Many thanks for this.

Let me double-check: the issue here is not the long time of the query, but the failure of jcf.t_get_taskinfo() to report memory usage, correct?

Thanks

Peter

Hi Peter,

My primary issue is actually the long slow query time.

However, I started the thread to get more info on the queries. jcf.t_get_taskinfo() does not give me the start time that I was originally looking for. I was hoping that info would help me track down the issue with the long slow queries. Your tip on modifying the logging is providing me the info that I need.

I actually don't need the start time from jcf.t_get_taskinfo() if the queries run faster. (but it would be a nice to have)

Are the slow query times typical or unusual?

I would appreciate any insights you may have to modify our environment to improve the performance of the long slow queries. (most queries are fast -- however it appears that the cartridge is choking on certain structures)

Cheers,

Guy

Hi Guy,

As far as I understand, if you execute your query separately, it takes ~6 minutes, but executing 15 queries at the same time (paralelly), then each of them takes ~107 minutes.

According to the log you sent, the screening phase of the search takes <1 minute and accepts only 6 target structures, for which the comprehensive search takes 5 minutes. It seems to be too long for such a few targets.

Questions:

1. What kind of structures do you have in the table? Could you send us the 6 structures that pass the screening phase, e.g. in a private email? (We can show you how to obtain them.)


2. What table type do you use? In particular, how did you create the JChem index, could you send us the code?


3. How many records do you have in the table?


4. Are you the only user who performed queries on the server at the time of these measurements.

Furthermore, note that even a single query is processed using a mulit-threaded search. In your case, all queries used 8 threads. Therefore, parallel queries are typically not faster than executing them sequentially (one after the other), they can even be slower.

Best regards,
Peter

Hi Guy,

Please omit the questions of my previous post. We just noticed that you use tautomer:y search option. It can answer the poor performance (even for a few targets), because tautomer searches are much slower than normal searches in JChem 5.12.

Recently, we have worked on improving this. In JChem 6.0, the tautomer full structure search became much faster (this is what you used: t:f tautomer:y). For your query, it could be about a hundred times faster. In the next major release (6.1), the tautomer full fragment search will also be improved to similar extent.

So I would recommend you to update to JChem 6.0 for much better performance in case of tautomer full structure search.

Best regards,
Peter

Hi Guy,

Did you perhaps managed to try your search in 6.1? I am curious to learn about your experiences with that.

 

Thanks,

Miklos