Re: Query hitting empty tables taking 48 minutes

> On Jun 7, 2018, at 1:14 PM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com> wrote:
>
> On 06/07/2018 11:55 AM, Robert Creager wrote:
>>> On Jun 7, 2018, at 12:40 PM, Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com <mailto:adrian(dot)klaver(at)aklaver(dot)com>> wrote:
>>>
>>> On 06/07/2018 11:17 AM, Robert Creager wrote:
>>>> I have a system running FreeBSD 11.1-STABLE, PostgreSQL 9.6.8,Java OpenJDK 1.8.0_131, jdbc 9.3-1104-jdbc41 which is exhibiting very bizarre behavior. A query is executing against a couple of tables that have 1 and 0 records in them. ds3.job_entry has 0 rows, ds3.blob has 1 row. If I execute the query manually via command line, it executes fine. There are no other active queries, no locks. The system is idle, in our Dev Test group, so I can leave it this way for a bit of time. The general software setup is in production and I’ve seen nothing like this before. Even a system with 300M ds3.blob entries executes this query fine.
>>>
>>> So I am assuming the problem query is being run through Java/jdbc, correct?
>> Yes.
>>>
>>> There is also the below in the log:
>>>
>>> " ... execute fetch from S_2037436/C_2037437 …"
>> So, that means nothing to me. Something to you?
>
> Just that the query being run from the code is going through a different path then the version you ran at the command line. Just trying to get to apples to apples if possible.
>
>>>
>>> My guess is that we will need to see the Java code that sets up and runs the query. Is that possible?
>> OMG, you had to ask ;-) Not really, for two reasons. It’s an actual shipping product, and I’d have to send you so much code to get from the source of the query down through the execute…. Now, the execute, on it’s own, is below. m_statement is a java.sql.PreparedStatement. Keep in mind this code is literally executing millions of times a day on a busy system. Except for this special snowflake system...
>
> I am not a Java programmer(hence the 'we' in my previous post), so someone who is will need to comment on the below. Though I have to believe the:
>
> m_statement.setFetchSize( 10000 );
>
> has got to do with:
>
> " ... execute fetch from S_2037436/C_2037437 …"
>
> In your OP you said the tables involved have 1 and 0 rows in them.

Yes.

>
> Is that from count(*) on each table?

Yes.

> Or is it for for job_id = 'b51357cd-e07a-4c87-a50b-999c347a5c71’?

There is no job_id entry, that table is empty.

Best,
Robert

>
>> private Executor executeQuery()
>> {
>> final MonitoredWork monitoredWork = new MonitoredWork(
>> StackTraceLogging.NONE, m_readableSql.getLogMessagePreExecution() );
>> try
>> {
>> m_closeTransactionUponClose = ( null == m_transactionNumber );
>> m_statement.setFetchSize( 10000 );
>> final Duration duration = new Duration();
>> m_resultSet = m_statement.executeQuery();
>> m_readableSql.log( duration, null );
>> return this;
>> }
>> catch ( final SQLException ex )
>> {
>> throw new DaoException(
>> "Failed to execute: " + m_readableSql.getLogMessagePreExecution(),
>> ex );
>> }
>> finally
>> {
>> monitoredWork.completed();
>> }
>> }
>>>
>
>>> --
>>> Adrian Klaver
>>> adrian(dot)klaver(at)aklaver(dot)com <mailto:adrian(dot)klaver(at)aklaver(dot)com>
>
>
> --
> Adrian Klaver
> adrian(dot)klaver(at)aklaver(dot)com