Re: Query hitting empty tables taking 48 minutes - Mailing list pgsql-general

On 06/07/2018 11:55 AM, Robert Creager wrote:
> 
> 
>> On Jun 7, 2018, at 12:40 PM, Adrian Klaver <adrian.klaver@aklaver.com 
>> <mailto:adrian.klaver@aklaver.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.

Is that from count(*) on each table?

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

> 
> 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.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com