Thread: Database transaction with intermittent slow responses

Database transaction with intermittent slow responses

From
John Gorman
Date:
Transactions to table, ChangeHistory, have recently become intermittently slow and is increasing becoming slower.
 
* No database configuration changes have been made recently
* We have run vacuum analyze
* We have tried backing up and reloading the table (data, indexes, etc)
 
Some transactions respond quickly (200 ms) and others take over 55 seconds (we cancel the query after 55 seconds – our timeout SLA). The problem has recently become very bad. It is the same query being issued but with different parameters.
 
If the transaction takes over 55 seconds and I run the query manually (with or without EXPLAIN ANALYZE) it returns quickly (a few hundred ms). In case I am looking at cache, I have a list of other queries (just different parameters) that have timed out and when I run them (without the limit even) the response is very timely.
 
Any help or insight would be great.
 
NOTE: our application is connecting to the database via JDBC and we are using PreparedStatements. I have provided full details so all information is available, but please let me know if any other information is needed – thx in advance.
 
p306=> EXPLAIN ANALYZE SELECT * FROM ChangeHistory WHERE Category BETWEEN 'Employee' AND 'Employeezz' AND PrimaryKeyOfChange BETWEEN '312313' AND '312313!zz' ORDER BY ChgTS DESC, ChgUser DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11;
                                            QUERY PLAN                                            
------------------------------------------------------------------------------------------------------
Limit  (cost=33.66..33.67 rows=1 width=136) (actual time=0.297..0.297 rows=11 loops=1)
   ->  Sort  (cost=33.66..33.67 rows=1 width=136) (actual time=0.297..0.297 rows=11 loops=1)
         Sort Key: chgts, chguser, category, primarykeyofchange
         Sort Method: top-N heapsort  Memory: 27kB
         ->  Index Scan using changehistory_idx4 on changehistory  (cost=0.00..33.65 rows=1 width=136) (actual time=0.046..
0.239 rows=85 loops=1)
               Index Cond: (((primarykeyofchange)::text >= '312313'::text) AND ((primarykeyofchange)::text <= '312313!zz'::
text))
               Filter: (((category)::text >= 'Employee'::text) AND ((category)::text <= 'Employeezz'::text))
Total runtime: 0.328 ms
(8 rows)
 
>>>
History this week of counts with good response times vs timeouts.
 
| Date       | Success # | Time Out # | Avg. Success Secs |
|------------+-----------+------------+-------------------|
| 2016-05-09 |        18 |         31 |               7.9 |
| 2016-05-10 |        17 |         25 |              10.5 |
| 2016-05-11 |        27 |         33 |              10.1 |
| 2016-05-12 |        68 |         24 |               9.9 |
 
 
>>> Sample transaction response times
 
| Timestamp         | Tran ID        | Resp MS | Resp CD
--------------------+----------------+---------+--------
2016-05-10 06:20:19 | ListChangeHist | 55,023  | TIMEOUT
2016-05-10 07:47:34 | ListChangeHist | 55,017  | TIMEOUT
2016-05-10 07:48:00 | ListChangeHist |  9,866  | OK
2016-05-10 07:48:10 | ListChangeHist |  2,327  | OK
2016-05-10 07:59:23 | ListChangeHist | 55,020  | TIMEOUT
2016-05-10 08:11:20 | ListChangeHist | 55,030  | TIMEOUT
2016-05-10 08:31:45 | ListChangeHist |  4,216  | OK
2016-05-10 08:35:09 | ListChangeHist |  7,898  | OK
2016-05-10 08:36:18 | ListChangeHist |  9,810  | OK
2016-05-10 08:36:56 | ListChangeHist | 55,027  | TIMEOUT
2016-05-10 08:37:33 | ListChangeHist | 46,433  | OK
2016-05-10 08:38:09 | ListChangeHist | 55,019  | TIMEOUT
2016-05-10 08:53:43 | ListChangeHist | 55,019  | TIMEOUT
2016-05-10 09:45:09 | ListChangeHist | 55,022  | TIMEOUT
2016-05-10 09:46:13 | ListChangeHist | 55,017  | TIMEOUT
2016-05-10 09:49:27 | ListChangeHist | 55,011  | TIMEOUT
2016-05-10 09:52:12 | ListChangeHist | 55,018  | TIMEOUT
2016-05-10 09:57:42 | ListChangeHist |  9,462  | OK
2016-05-10 10:05:21 | ListChangeHist | 55,016  | TIMEOUT
2016-05-10 10:05:29 | ListChangeHist |    136  | OK
2016-05-10 10:05:38 | ListChangeHist |  1,517  | OK
 
Artifacts
======================
 
$ >uname -a
SunOS ***** 5.10 Generic_150400-30 sun4v sparc sun4v
 
Memory    : 254G phys mem, 207G free mem.
Processors: 32 - CPU is mostly 80% free
 
>>>
p306=> select version();
                                                      version                                                     
---------------------------------------------------------------------------------------------------
PostgreSQL 9.1.14 on sparc-sun-solaris2.10, compiled by gcc (GCC) 3.4.3 (csl-sol210-3_4-branch+sol_rpath), 64-bit
 
>>>
p306=> \dt+ changehistory
                      List of relations
Schema |     Name      | Type  | Owner | Size  | Description
--------+---------------+-------+-------+-------+-------------
public | changehistory | table | p306  | 17 GB |
 
>>>
p306=> \di+ changehistory*
                                   List of relations
Schema |         Name          | Type  | Owner |     Table     |  Size   | Description
--------+-----------------------+-------+-------+---------------+---------+-------------
public | changehistory_idx1    | index | p306  | changehistory | 9597 MB |
public | changehistory_idx3    | index | p306  | changehistory | 11 GB   |
public | changehistory_idx4    | index | p306  | changehistory | 4973 MB |
public | changehistory_pkey    | index | p306  | changehistory | 2791 MB |
public | changehistory_search2 | index | p306  | changehistory | 9888 MB |
public | changehistory_search3 | index | p306  | changehistory | 10 GB   |
public | changehistory_search4 | index | p306  | changehistory | 9240 MB |
public | changehistory_search5 | index | p306  | changehistory | 8373 MB |
(8 rows)
 
 
>>>
p306=> select count(*) from changehistory ;
   count  
------------
129,185,024
 
>>>
Show all (filtered)
======================================================
 
              name               | setting
---------------------------------+--------------------
autovacuum                      | on
autovacuum_analyze_scale_factor | 0.001
autovacuum_analyze_threshold    | 500
autovacuum_freeze_max_age       | 200000000
autovacuum_max_workers          | 5
autovacuum_naptime              | 1min
autovacuum_vacuum_cost_delay    | 0
autovacuum_vacuum_cost_limit    | -1
autovacuum_vacuum_scale_factor  | 0.001
autovacuum_vacuum_threshold     | 500
bgwriter_delay                  | 200ms
block_size                      | 8192
check_function_bodies           | on
checkpoint_completion_target    | 0.9
checkpoint_segments             | 256
checkpoint_timeout              | 1h
checkpoint_warning              | 30s
client_encoding                 | UTF8
commit_delay                    | 0
commit_siblings                 | 5
cpu_index_tuple_cost            | 0.005
cpu_operator_cost               | 0.0025
cpu_tuple_cost                  | 0.01
cursor_tuple_fraction           | 0.1
deadlock_timeout                | 1s
default_statistics_target       | 100
default_transaction_deferrable  | off
default_transaction_isolation   | read committed
default_transaction_read_only   | off
default_with_oids               | off
effective_cache_size            | 8GB
from_collapse_limit             | 8
fsync                           | on
full_page_writes                | on
ignore_system_indexes           | off
join_collapse_limit             | 8
krb_caseins_users               | off
lo_compat_privileges            | off
maintenance_work_mem            | 1GB
max_connections                 | 350
max_files_per_process           | 1000
max_function_args               | 100
max_identifier_length           | 63
max_index_keys                  | 32
max_locks_per_transaction       | 64
max_pred_locks_per_transaction  | 64
max_prepared_transactions       | 0
max_stack_depth                 | 2MB
max_wal_senders                 | 5
random_page_cost                | 4
segment_size                    | 1GB
seq_page_cost                   | 1
server_encoding                 | UTF8
server_version                  | 9.1.14
shared_buffers                  | 2GB
sql_inheritance                 | on
statement_timeout               | 0
synchronize_seqscans            | on
synchronous_commit              | on
synchronous_standby_names       |
tcp_keepalives_count            | 0
tcp_keepalives_idle             | -1
tcp_keepalives_interval         | 0
track_activities                | on
track_activity_query_size       | 1024
track_counts                    | on
track_functions                 | none
transaction_deferrable          | off
transaction_isolation           | read committed
transaction_read_only           | off
transform_null_equals           | off
update_process_title            | on
vacuum_cost_delay               | 0
vacuum_cost_limit               | 200
vacuum_cost_page_dirty          | 20
vacuum_cost_page_hit            | 1
vacuum_cost_page_miss           | 10
vacuum_defer_cleanup_age        | 0
vacuum_freeze_min_age           | 50000000
vacuum_freeze_table_age         | 150000000
 
John Gorman | Manager of Production Support, Architecture, Release Engineering | Eldorado | a Division of MPHASIS | www.eldoinc.com/ |
5353 North 16th Street, Suite 400, Phoenix, Arizona 85016-3228 | Tel 602.604.3100 | Fax: 602.604.3115
 
 
 

Re: Database transaction with intermittent slow responses

From
Gerardo Herzig
Date:
After quick reading, im thinking about a couples of chances:

1) You are hitting a connection_limit
2) You are hitting a lock contention (perhaps some other backend is locking the table and not releasing it)

Who throws the timeout? It is Postgres or your JDBC connector?

My initial blind guess is that your "timed out queries" never gets postgres at all, and are blocked prior to that for
someother issue. If im wrong, well, you should at least have the timeout recorded in your logs. 

You should also track #of_connectinos and #of_locks over that tables.

See http://www.postgresql.org/docs/9.1/static/view-pg-locks.html for pg_lock information

That should be my starting point for viewing whats going on.

HTH
Gerardo

----- Mensaje original -----
> De: "John Gorman" <jgorman@eldocomp.com>
> Para: pgsql-performance@postgresql.org
> CC: "John Gorman" <jgorman@eldocomp.com>
> Enviados: Viernes, 13 de Mayo 2016 16:59:51
> Asunto: [PERFORM] Database transaction with intermittent slow responses
>
>
> Transactions to table, ChangeHistory, have recently become
> intermittently slow and is increasing becoming slower.
>
> * No database configuration changes have been made recently
> * We have run vacuum analyze
> * We have tried backing up and reloading the table (data, indexes,
> etc)
>
> Some transactions respond quickly (200 ms) and others take over 55
> seconds (we cancel the query after 55 seconds – our timeout SLA).
> The problem has recently become very bad. It is the same query being
> issued but with different parameters.
>
> If the transaction takes over 55 seconds and I run the query manually
> (with or without EXPLAIN ANALYZE) it returns quickly (a few hundred
> ms). In case I am looking at cache, I have a list of other queries
> (just different parameters) that have timed out and when I run them
> (without the limit even) the response is very timely.
>
> Any help or insight would be great.
>
> NOTE: our application is connecting to the database via JDBC and we
> are using PreparedStatements. I have provided full details so all
> information is available, but please let me know if any other
> information is needed – thx in advance.
>
> p306=> EXPLAIN ANALYZE SELECT * FROM ChangeHistory WHERE Category
> BETWEEN 'Employee' AND 'Employeezz' AND PrimaryKeyOfChange BETWEEN
> '312313' AND '312313!zz' ORDER BY ChgTS DESC, ChgUser DESC, Category
> DESC, PrimaryKeyOfChange DESC LIMIT 11;
> QUERY PLAN
> ------------------------------------------------------------------------------------------------------
> Limit (cost=33.66..33.67 rows=1 width=136) (actual time=0.297..0.297
> rows=11 loops=1)
> -> Sort (cost=33.66..33.67 rows=1 width=136) (actual
> time=0.297..0.297 rows=11 loops=1)
> Sort Key: chgts, chguser, category, primarykeyofchange
> Sort Method: top-N heapsort Memory: 27kB
> -> Index Scan using changehistory_idx4 on changehistory
> (cost=0.00..33.65 rows=1 width=136) (actual time=0.046..
> 0.239 rows=85 loops=1)
> Index Cond: (((primarykeyofchange)::text >= '312313'::text) AND
> ((primarykeyofchange)::text <= '312313!zz'::
> text))
> Filter: (((category)::text >= 'Employee'::text) AND ((category)::text
> <= 'Employeezz'::text))
> Total runtime: 0.328 ms
> (8 rows)
>
> >>>
> History this week of counts with good response times vs timeouts.
>
> | Date | Success # | Time Out # | Avg. Success Secs |
> |------------+-----------+------------+-------------------|
> | 2016-05-09 | 18 | 31 | 7.9 |
> | 2016-05-10 | 17 | 25 | 10.5 |
> | 2016-05-11 | 27 | 33 | 10.1 |
> | 2016-05-12 | 68 | 24 | 9.9 |
>
>
> >>> Sample transaction response times
>
> | Timestamp | Tran ID | Resp MS | Resp CD
> --------------------+----------------+---------+--------
> 2016-05-10 06:20:19 | ListChangeHist | 55,023 | TIMEOUT
> 2016-05-10 07:47:34 | ListChangeHist | 55,017 | TIMEOUT
> 2016-05-10 07:48:00 | ListChangeHist | 9,866 | OK
> 2016-05-10 07:48:10 | ListChangeHist | 2,327 | OK
> 2016-05-10 07:59:23 | ListChangeHist | 55,020 | TIMEOUT
> 2016-05-10 08:11:20 | ListChangeHist | 55,030 | TIMEOUT
> 2016-05-10 08:31:45 | ListChangeHist | 4,216 | OK
> 2016-05-10 08:35:09 | ListChangeHist | 7,898 | OK
> 2016-05-10 08:36:18 | ListChangeHist | 9,810 | OK
> 2016-05-10 08:36:56 | ListChangeHist | 55,027 | TIMEOUT
> 2016-05-10 08:37:33 | ListChangeHist | 46,433 | OK
> 2016-05-10 08:38:09 | ListChangeHist | 55,019 | TIMEOUT
> 2016-05-10 08:53:43 | ListChangeHist | 55,019 | TIMEOUT
> 2016-05-10 09:45:09 | ListChangeHist | 55,022 | TIMEOUT
> 2016-05-10 09:46:13 | ListChangeHist | 55,017 | TIMEOUT
> 2016-05-10 09:49:27 | ListChangeHist | 55,011 | TIMEOUT
> 2016-05-10 09:52:12 | ListChangeHist | 55,018 | TIMEOUT
> 2016-05-10 09:57:42 | ListChangeHist | 9,462 | OK
> 2016-05-10 10:05:21 | ListChangeHist | 55,016 | TIMEOUT
> 2016-05-10 10:05:29 | ListChangeHist | 136 | OK
> 2016-05-10 10:05:38 | ListChangeHist | 1,517 | OK
>
> Artifacts
> ======================
>
> $ >uname -a
> SunOS ***** 5.10 Generic_150400-30 sun4v sparc sun4v
>
> Memory : 254G phys mem, 207G free mem.
> Processors: 32 - CPU is mostly 80% free
>
> >>>
> p306=> select version();
> version
> ---------------------------------------------------------------------------------------------------
> PostgreSQL 9.1.14 on sparc-sun-solaris2.10, compiled by gcc (GCC)
> 3.4.3 (csl-sol210-3_4-branch+sol_rpath), 64-bit
>
> >>>
> p306=> \dt+ changehistory
> List of relations
> Schema | Name | Type | Owner | Size | Description
> --------+---------------+-------+-------+-------+-------------
> public | changehistory | table | p306 | 17 GB |
>
> >>>
> p306=> \di+ changehistory*
> List of relations
> Schema | Name | Type | Owner | Table | Size | Description
> --------+-----------------------+-------+-------+---------------+---------+-------------
> public | changehistory_idx1 | index | p306 | changehistory | 9597 MB
> |
> public | changehistory_idx3 | index | p306 | changehistory | 11 GB |
> public | changehistory_idx4 | index | p306 | changehistory | 4973 MB
> |
> public | changehistory_pkey | index | p306 | changehistory | 2791 MB
> |
> public | changehistory_search2 | index | p306 | changehistory | 9888
> MB |
> public | changehistory_search3 | index | p306 | changehistory | 10 GB
> |
> public | changehistory_search4 | index | p306 | changehistory | 9240
> MB |
> public | changehistory_search5 | index | p306 | changehistory | 8373
> MB |
> (8 rows)
>
>
> >>>
> p306=> select count(*) from changehistory ;
> count
> ------------
> 129,185,024
>
> >>>
> Show all (filtered)
> ======================================================
>
> name | setting
> ---------------------------------+--------------------
> autovacuum | on
> autovacuum_analyze_scale_factor | 0.001
> autovacuum_analyze_threshold | 500
> autovacuum_freeze_max_age | 200000000
> autovacuum_max_workers | 5
> autovacuum_naptime | 1min
> autovacuum_vacuum_cost_delay | 0
> autovacuum_vacuum_cost_limit | -1
> autovacuum_vacuum_scale_factor | 0.001
> autovacuum_vacuum_threshold | 500
> bgwriter_delay | 200ms
> block_size | 8192
> check_function_bodies | on
> checkpoint_completion_target | 0.9
> checkpoint_segments | 256
> checkpoint_timeout | 1h
> checkpoint_warning | 30s
> client_encoding | UTF8
> commit_delay | 0
> commit_siblings | 5
> cpu_index_tuple_cost | 0.005
> cpu_operator_cost | 0.0025
> cpu_tuple_cost | 0.01
> cursor_tuple_fraction | 0.1
> deadlock_timeout | 1s
> default_statistics_target | 100
> default_transaction_deferrable | off
> default_transaction_isolation | read committed
> default_transaction_read_only | off
> default_with_oids | off
> effective_cache_size | 8GB
> from_collapse_limit | 8
> fsync | on
> full_page_writes | on
> ignore_system_indexes | off
> join_collapse_limit | 8
> krb_caseins_users | off
> lo_compat_privileges | off
> maintenance_work_mem | 1GB
> max_connections | 350
> max_files_per_process | 1000
> max_function_args | 100
> max_identifier_length | 63
> max_index_keys | 32
> max_locks_per_transaction | 64
> max_pred_locks_per_transaction | 64
> max_prepared_transactions | 0
> max_stack_depth | 2MB
> max_wal_senders | 5
> random_page_cost | 4
> segment_size | 1GB
> seq_page_cost | 1
> server_encoding | UTF8
> server_version | 9.1.14
> shared_buffers | 2GB
> sql_inheritance | on
> statement_timeout | 0
> synchronize_seqscans | on
> synchronous_commit | on
> synchronous_standby_names |
> tcp_keepalives_count | 0
> tcp_keepalives_idle | -1
> tcp_keepalives_interval | 0
> track_activities | on
> track_activity_query_size | 1024
> track_counts | on
> track_functions | none
> transaction_deferrable | off
> transaction_isolation | read committed
> transaction_read_only | off
> transform_null_equals | off
> update_process_title | on
> vacuum_cost_delay | 0
> vacuum_cost_limit | 200
> vacuum_cost_page_dirty | 20
> vacuum_cost_page_hit | 1
> vacuum_cost_page_miss | 10
> vacuum_defer_cleanup_age | 0
> vacuum_freeze_min_age | 50000000
> vacuum_freeze_table_age | 150000000
>
> John Gorman | Manager of Production Support, Architecture, Release
> Engineering | Eldorado | a Division of M PHASI S | www.eldoinc.com/
> |
> 5353 North 16 th Street, Suite 400, Phoenix, Arizona 85016-3228 | Tel
> 602.604.3100 | Fax: 602.604.3115
>
>
>


Re: Database transaction with intermittent slow responses

From
John Gorman
Date:
Hi Gerado,

Thanks for the quick response. We do not appear to have a connection limit since our application is the only thing
talkingto the database, the connections are somewhat limited. We are using about 126 of a max allowed 350 connections.
Wekeep these metrics in a different database, and we also generate alerts if we get close to the catalog/cluster
limit.

Also I have been monitoring heavily and watching for locks while the transaction runs for a long time. While I see
occasionallocks, they are on other tables and are brief, so I do not believe there is a database lock
issue/contention.

The application is timing the transaction out. When we detect that the timeout limit has occurred, we cancel the
databaseconnection (conn.cancel();) - we have been doing this for several years with no issue.
 

I setup a adhoc monitor which runs every 2 seconds and displays "select * from pg_stat_activity where datname = 'p306'
andcurrent_query not like '<IDLE%'; and then write the output to a log. I can see the transaction being executed in the
databasefor over 50 seconds, so I do believe the database actually is working on it.
 

We have a few monitoring programs that track and record quite a few thinks including database locks (number and type),
connections(number and where). I have reviewed the history and do not see any trends.
 

If it helps here is a monitor snippet of the transaction taking over 50 seconds (SELECT * FROM ChangeHistory)


>> Wed May 11 07:50:09 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       59871 |
2016-05-1107:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
ChangeHistoryWHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
DESC,Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 

>> Wed May 11 07:50:11 MST 2016
 3709009 | p306    |   15014 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       35859
|2016-05-11 07:31:31.968087-07 | 2016-05-11 07:50:11.575881-07 | 2016-05-11 07:50:11.766942-07 | f       | SELECT *
FROMEmployee WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName, FirstName, MiddleName, BlkOfBusID,
ClientID,CertificateNumber, SocialSecurityNumber, MedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:11.712848-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:11.712887-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:13 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:13.733643-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   16771 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       37470
|2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:13.770366-07 | 2016-05-11 07:50:13.811502-07 | f       | SELECT *
FROMDependent WHERE DependentID = $1
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:13.733968-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:15 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:15.734777-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:15.73486-07  | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:17 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       59871 |
2016-05-1107:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
ChangeHistoryWHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
DESC,Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 

>> Wed May 11 07:50:19 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       59871 |
2016-05-1107:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
ChangeHistoryWHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
DESC,Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 

>> Wed May 11 07:50:21 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       59871 |
2016-05-1107:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
ChangeHistoryWHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
DESC,Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   21656 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       41810 |
2016-05-1107:48:40.95846-07  | 2016-05-11 07:50:21.871077-07 | 2016-05-11 07:50:21.871579-07 | f       | DELETE FROM
ClaimPrevQueueWHERE Claimnumber = $1
 
 3709009 | p306    |    8042 |    16387 | p306    |                  | 172.20.0.82 | coreb           |       63023 |
2016-05-1107:14:34.208098-07 | 2016-05-11 07:50:21.813662-07 | 2016-05-11 07:50:21.814575-07 | f       | SELECT * FROM
EmployeeWHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName, FirstName, MiddleName, BlkOfBusID, ClientID,
CertificateNumber,SocialSecurityNumber, MedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 

>> Wed May 11 07:50:23 MST 2016
 3709009 | p306    |    5644 |    16387 | p306     |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306     |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:23.85706-07  | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    7925 |    16387 | p306     |                  | 172.20.0.82 | coreb               |       62888
|2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 | 2016-05-11 07:50:23.684134-07 | f       | DELETE FROM
ToothChartMaintenanceWHERE Claimnumber = $1
 
 3709009 | p306    |    8671 |    16387 | p306     |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:23.857092-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   22235 |       10 | postgres |                  |             |                     |
|2016-05-11 07:50:22.129887-07 | 2016-05-11 07:50:22.162326-07 | 2016-05-11 07:50:22.162326-07 | f       | autovacuum:
VACUUMpublic.adjrespendrsncode
 

>> Wed May 11 07:50:25 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |    7925 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       62888
|2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 | 2016-05-11 07:50:25.931788-07 | f       | SELECT *
FROMCategoryPlaceService WHERE CategoryID = $1 ORDER BY CategoryID, RangeFrom, RangeTo LIMIT 1000
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:25.920308-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:27 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:27.935677-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:27.938329-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:29 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17652 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       38402
|2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:29.615446-07 | 2016-05-11 07:50:29.954405-07 | f       | SELECT *
FROMDependent WHERE DepSocialSecurityNumber BETWEEN $1 AND $2 ORDER BY DepCertificateNumber, DepSocialSecurityNumber,
DepLastName,DepFirstName, DepMiddleName, DepMedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:29.966428-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:29.966481-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:31 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:32.000148-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:34 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:33.953492-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:33.953803-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:36 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:35.996862-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:35.996892-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:38 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:38.039441-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:38.036922-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:40 MST 2016
 3709009 | p306    |   17321 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       38226
|2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:40.059438-07 | 2016-05-11 07:50:40.060951-07 | f       | DELETE FROM
ClaimPrevQueueWHERE Claimnumber = $1
 
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |    2860 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       56427
|2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:40.060863-07 | 2016-05-11 07:50:40.062051-07 | f       | SELECT *
FROMEmployee WHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName, FirstName, MiddleName, BlkOfBusID, ClientID,
CertificateNumber,SocialSecurityNumber, MedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 
 3709009 | p306    |   17652 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       38402
|2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:40.059956-07 | 2016-05-11 07:50:40.083659-07 | f       | DELETE FROM
ToothChartMaintenanceWHERE Claimnumber = $1
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:40.077061-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   16771 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       37470
|2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:40.060076-07 | 2016-05-11 07:50:40.072735-07 | f       | INSERT INTO
CrmCallLinksVALUES
($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27)
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:40.080967-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   18895 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       39389
|2016-05-11 07:42:04.682022-07 | 2016-05-11 07:50:40.062356-07 | 2016-05-11 07:50:40.062667-07 | f       | SELECT *
FROMRealtimeTransInfo WHERE SenderID = $1 AND PayLoadID = $2 ORDER BY SenderID DESC, PayLoadID DESC LIMIT 2
 
 3709009 | p306    |    8864 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       64407
|2016-05-11 07:18:34.848657-07 | 2016-05-11 07:50:39.601078-07 | 2016-05-11 07:50:40.077433-07 | f       | SELECT *
FROMFacility WHERE FacilityID = $1
 

>> Wed May 11 07:50:42 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |    2860 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       56427
|2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:42.094681-07 | 2016-05-11 07:50:42.095179-07 | f       | DELETE FROM
ClaimPrevQueueWHERE Claimnumber = $1
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:42.023507-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:42.023043-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:44 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:44.054554-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:44.054674-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:46 MST 2016
 3709009 | p306    |   17321 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       38226
|2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:45.908151-07 | 2016-05-11 07:50:46.08959-07  | f       | SELECT *
FROMEmployee WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName, FirstName, MiddleName, BlkOfBusID,
ClientID,CertificateNumber, SocialSecurityNumber, MedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:46.077355-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   16771 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       37470
|2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:46.139211-07 | 2016-05-11 07:50:46.141386-07 | f       | SELECT *
FROMAdjudicationResult WHERE Claimnumber BETWEEN $1 AND $2 ORDER BY Claimnumber DESC LIMIT 11
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:46.067222-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:48 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:48.082695-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:48.082883-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:50 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |    2860 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       56427
|2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:50.056892-07 | 2016-05-11 07:50:50.174587-07 | f       | SELECT *
FROMEmployee WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName, FirstName, MiddleName, BlkOfBusID,
ClientID,CertificateNumber, SocialSecurityNumber, MedicareID, BirthDate, AlternateID1, AlternateID2 LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:50.107102-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    5620 |    16387 | p306    | TaskRunner       | 172.20.0.86 | batchb.eldocomp.com |       37594
|2016-05-11 07:04:08.129626-07 | 2016-05-11 07:50:49.812093-07 | 2016-05-11 07:50:49.81238-07  | f       | SELECT *
FROMEDIFtpFileDetails WHERE MsgLogStatus = $1 AND ProcessId > $2 ORDER BY MsgLogStatus, ProcessId LIMIT 10
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:50.107172-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:52 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:52.127455-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:52.127776-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:54 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:54.165381-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:54.165596-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:56 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:56.189515-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:56.176308-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:50:58 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   21656 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       41810
|2016-05-11 07:48:40.95846-07  | 2016-05-11 07:50:56.785032-07 | 2016-05-11 07:50:56.789767-07 | f       | SELECT *
FROMFacilityPhysicianAffl WHERE  Status IN ('A', 'H', 'D') AND (FacilityID IN (SELECT FacilityID FROM Facility WHERE
UPPER(TaxID)='811190101' AND Status IN (  'A' ,  'H' ,  'D')  ) AND  ( PhysicianID IN (SELECT PhysicianID FROM
PhysicianWHERE Status IN (  'A' ,  'H' ,  'D')  )) AND (( ISDUMMY='0' AND FacilityID IN ( SELECT FacilityID FROM
FacilityWHERE FacilityRecordType = 'S' AND  ( FacilityName IS NOT NULL AND FacilityName != '' ) )  OR ( FacilityID IN (
SELECTFacilityID FROM Facility WHERE FacilityRecordType = 'F' AND  ( FacilityName IS NOT NULL AND FacilityName != '' )
)))))ORDER BY FacilityID ASC , PhysicianID ASC
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:50:58.212226-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:50:58.269389-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:51:00 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:51:00.228846-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:51:00.229019-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:51:02 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |    4715 |    16387 | p306    | TaskRunner       | 172.20.0.86 | batchb.eldocomp.com |       33881
|2016-05-11 07:01:41.247388-07 | 2016-05-11 07:51:02.125906-07 | 2016-05-11 07:51:02.311956-07 | f       | SELECT *
FROMEmpEligibilityCoverage WHERE EmployeeID = $1 AND EffectiveDate <= $2 ORDER BY EmployeeID DESC, EffectiveDate DESC
LIMIT101
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:51:02.23586-07  | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |   16771 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       37470
|2016-05-11 07:36:18.535139-07 | 2016-05-11 07:51:02.188886-07 | 2016-05-11 07:51:02.295888-07 | f       | DELETE FROM
ToothChartMaintenanceWHERE Claimnumber = $1
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:51:02.235869-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:51:04 MST 2016
 3709009 | p306    |    5644 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       59871
|2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 | 2016-05-11 07:50:09.396161-07 | f       | SELECT *
FROMChangeHistory WHERE Category BETWEEN $1 AND $2 AND PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC,
ChgUserDESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:51:04.277287-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:51:04.277543-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:51:06 MST 2016
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:51:06.313649-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:51:06.313855-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

>> Wed May 11 07:51:08 MST 2016
 3709009 | p306    |   22530 |    16387 | p306    |                  | 172.20.0.82 | coreb               |       42494
|2016-05-11 07:51:04.419169-07 | 2016-05-11 07:51:08.351721-07 | 2016-05-11 07:51:08.373929-07 | f       | SELECT *
FROMChangeHistory WHERE Category = $1 AND PrimaryKeyOfChange = $2 ORDER BY Category, PrimaryKeyOfChange, ChgTS,
ExcludedKeyFieldsLIMIT 2001
 
 3709009 | p306    |   17312 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       54263
|2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 | 2016-05-11 07:51:08.335854-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 
 3709009 | p306    |    8671 |    16387 | p306    |                  | 172.20.0.86 | batchb.eldocomp.com |       55055
|2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 | 2016-05-11 07:51:08.359281-07 | f       | SELECT *
FROMEmployee WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
 

Regards
John

-----Original Message-----
From: Gerardo Herzig [mailto:gherzig@fmed.uba.ar] 
Sent: Friday, May 13, 2016 2:05 PM
To: John Gorman
Cc: pgsql-performance@postgresql.org
Subject: Re: [PERFORM] Database transaction with intermittent slow responses

After quick reading, im thinking about a couples of chances:

1) You are hitting a connection_limit
2) You are hitting a lock contention (perhaps some other backend is locking the table and not releasing it)

Who throws the timeout? It is Postgres or your JDBC connector?

My initial blind guess is that your "timed out queries" never gets postgres at all, and are blocked prior to that for
someother issue. If im wrong, well, you should at least have the timeout recorded in your logs.
 

You should also track #of_connectinos and #of_locks over that tables.

See http://www.postgresql.org/docs/9.1/static/view-pg-locks.html for pg_lock information

That should be my starting point for viewing whats going on.

HTH
Gerardo

----- Mensaje original -----
> De: "John Gorman" <jgorman@eldocomp.com>
> Para: pgsql-performance@postgresql.org
> CC: "John Gorman" <jgorman@eldocomp.com>
> Enviados: Viernes, 13 de Mayo 2016 16:59:51
> Asunto: [PERFORM] Database transaction with intermittent slow responses
> 
> 
> Transactions to table, ChangeHistory, have recently become
> intermittently slow and is increasing becoming slower.
> 
> * No database configuration changes have been made recently
> * We have run vacuum analyze
> * We have tried backing up and reloading the table (data, indexes,
> etc)
> 
> Some transactions respond quickly (200 ms) and others take over 55
> seconds (we cancel the query after 55 seconds – our timeout SLA).
> The problem has recently become very bad. It is the same query being
> issued but with different parameters.
> 
> If the transaction takes over 55 seconds and I run the query manually
> (with or without EXPLAIN ANALYZE) it returns quickly (a few hundred
> ms). In case I am looking at cache, I have a list of other queries
> (just different parameters) that have timed out and when I run them
> (without the limit even) the response is very timely.
> 
> Any help or insight would be great.
> 
> NOTE: our application is connecting to the database via JDBC and we
> are using PreparedStatements. I have provided full details so all
> information is available, but please let me know if any other
> information is needed – thx in advance.
> 
> p306=> EXPLAIN ANALYZE SELECT * FROM ChangeHistory WHERE Category
> BETWEEN 'Employee' AND 'Employeezz' AND PrimaryKeyOfChange BETWEEN
> '312313' AND '312313!zz' ORDER BY ChgTS DESC, ChgUser DESC, Category
> DESC, PrimaryKeyOfChange DESC LIMIT 11;
> QUERY PLAN
> ------------------------------------------------------------------------------------------------------
> Limit (cost=33.66..33.67 rows=1 width=136) (actual time=0.297..0.297
> rows=11 loops=1)
> -> Sort (cost=33.66..33.67 rows=1 width=136) (actual
> time=0.297..0.297 rows=11 loops=1)
> Sort Key: chgts, chguser, category, primarykeyofchange
> Sort Method: top-N heapsort Memory: 27kB
> -> Index Scan using changehistory_idx4 on changehistory
> (cost=0.00..33.65 rows=1 width=136) (actual time=0.046..
> 0.239 rows=85 loops=1)
> Index Cond: (((primarykeyofchange)::text >= '312313'::text) AND
> ((primarykeyofchange)::text <= '312313!zz'::
> text))
> Filter: (((category)::text >= 'Employee'::text) AND ((category)::text
> <= 'Employeezz'::text))
> Total runtime: 0.328 ms
> (8 rows)
> 
> >>> 
> History this week of counts with good response times vs timeouts.
> 
> | Date | Success # | Time Out # | Avg. Success Secs |
> |------------+-----------+------------+-------------------|
> | 2016-05-09 | 18 | 31 | 7.9 |
> | 2016-05-10 | 17 | 25 | 10.5 |
> | 2016-05-11 | 27 | 33 | 10.1 |
> | 2016-05-12 | 68 | 24 | 9.9 |
> 
> 
> >>> Sample transaction response times
> 
> | Timestamp | Tran ID | Resp MS | Resp CD
> --------------------+----------------+---------+--------
> 2016-05-10 06:20:19 | ListChangeHist | 55,023 | TIMEOUT
> 2016-05-10 07:47:34 | ListChangeHist | 55,017 | TIMEOUT
> 2016-05-10 07:48:00 | ListChangeHist | 9,866 | OK
> 2016-05-10 07:48:10 | ListChangeHist | 2,327 | OK
> 2016-05-10 07:59:23 | ListChangeHist | 55,020 | TIMEOUT
> 2016-05-10 08:11:20 | ListChangeHist | 55,030 | TIMEOUT
> 2016-05-10 08:31:45 | ListChangeHist | 4,216 | OK
> 2016-05-10 08:35:09 | ListChangeHist | 7,898 | OK
> 2016-05-10 08:36:18 | ListChangeHist | 9,810 | OK
> 2016-05-10 08:36:56 | ListChangeHist | 55,027 | TIMEOUT
> 2016-05-10 08:37:33 | ListChangeHist | 46,433 | OK
> 2016-05-10 08:38:09 | ListChangeHist | 55,019 | TIMEOUT
> 2016-05-10 08:53:43 | ListChangeHist | 55,019 | TIMEOUT
> 2016-05-10 09:45:09 | ListChangeHist | 55,022 | TIMEOUT
> 2016-05-10 09:46:13 | ListChangeHist | 55,017 | TIMEOUT
> 2016-05-10 09:49:27 | ListChangeHist | 55,011 | TIMEOUT
> 2016-05-10 09:52:12 | ListChangeHist | 55,018 | TIMEOUT
> 2016-05-10 09:57:42 | ListChangeHist | 9,462 | OK
> 2016-05-10 10:05:21 | ListChangeHist | 55,016 | TIMEOUT
> 2016-05-10 10:05:29 | ListChangeHist | 136 | OK
> 2016-05-10 10:05:38 | ListChangeHist | 1,517 | OK
> 
> Artifacts
> ======================
> 
> $ >uname -a
> SunOS ***** 5.10 Generic_150400-30 sun4v sparc sun4v
> 
> Memory : 254G phys mem, 207G free mem.
> Processors: 32 - CPU is mostly 80% free
> 
> >>> 
> p306=> select version();
> version
> ---------------------------------------------------------------------------------------------------
> PostgreSQL 9.1.14 on sparc-sun-solaris2.10, compiled by gcc (GCC)
> 3.4.3 (csl-sol210-3_4-branch+sol_rpath), 64-bit
> 
> >>> 
> p306=> \dt+ changehistory
> List of relations
> Schema | Name | Type | Owner | Size | Description
> --------+---------------+-------+-------+-------+-------------
> public | changehistory | table | p306 | 17 GB |
> 
> >>> 
> p306=> \di+ changehistory*
> List of relations
> Schema | Name | Type | Owner | Table | Size | Description
> --------+-----------------------+-------+-------+---------------+---------+-------------
> public | changehistory_idx1 | index | p306 | changehistory | 9597 MB
> |
> public | changehistory_idx3 | index | p306 | changehistory | 11 GB |
> public | changehistory_idx4 | index | p306 | changehistory | 4973 MB
> |
> public | changehistory_pkey | index | p306 | changehistory | 2791 MB
> |
> public | changehistory_search2 | index | p306 | changehistory | 9888
> MB |
> public | changehistory_search3 | index | p306 | changehistory | 10 GB
> |
> public | changehistory_search4 | index | p306 | changehistory | 9240
> MB |
> public | changehistory_search5 | index | p306 | changehistory | 8373
> MB |
> (8 rows)
> 
> 
> >>> 
> p306=> select count(*) from changehistory ;
> count
> ------------
> 129,185,024
> 
> >>> 
> Show all (filtered)
> ======================================================
> 
> name | setting
> ---------------------------------+--------------------
> autovacuum | on
> autovacuum_analyze_scale_factor | 0.001
> autovacuum_analyze_threshold | 500
> autovacuum_freeze_max_age | 200000000
> autovacuum_max_workers | 5
> autovacuum_naptime | 1min
> autovacuum_vacuum_cost_delay | 0
> autovacuum_vacuum_cost_limit | -1
> autovacuum_vacuum_scale_factor | 0.001
> autovacuum_vacuum_threshold | 500
> bgwriter_delay | 200ms
> block_size | 8192
> check_function_bodies | on
> checkpoint_completion_target | 0.9
> checkpoint_segments | 256
> checkpoint_timeout | 1h
> checkpoint_warning | 30s
> client_encoding | UTF8
> commit_delay | 0
> commit_siblings | 5
> cpu_index_tuple_cost | 0.005
> cpu_operator_cost | 0.0025
> cpu_tuple_cost | 0.01
> cursor_tuple_fraction | 0.1
> deadlock_timeout | 1s
> default_statistics_target | 100
> default_transaction_deferrable | off
> default_transaction_isolation | read committed
> default_transaction_read_only | off
> default_with_oids | off
> effective_cache_size | 8GB
> from_collapse_limit | 8
> fsync | on
> full_page_writes | on
> ignore_system_indexes | off
> join_collapse_limit | 8
> krb_caseins_users | off
> lo_compat_privileges | off
> maintenance_work_mem | 1GB
> max_connections | 350
> max_files_per_process | 1000
> max_function_args | 100
> max_identifier_length | 63
> max_index_keys | 32
> max_locks_per_transaction | 64
> max_pred_locks_per_transaction | 64
> max_prepared_transactions | 0
> max_stack_depth | 2MB
> max_wal_senders | 5
> random_page_cost | 4
> segment_size | 1GB
> seq_page_cost | 1
> server_encoding | UTF8
> server_version | 9.1.14
> shared_buffers | 2GB
> sql_inheritance | on
> statement_timeout | 0
> synchronize_seqscans | on
> synchronous_commit | on
> synchronous_standby_names |
> tcp_keepalives_count | 0
> tcp_keepalives_idle | -1
> tcp_keepalives_interval | 0
> track_activities | on
> track_activity_query_size | 1024
> track_counts | on
> track_functions | none
> transaction_deferrable | off
> transaction_isolation | read committed
> transaction_read_only | off
> transform_null_equals | off
> update_process_title | on
> vacuum_cost_delay | 0
> vacuum_cost_limit | 200
> vacuum_cost_page_dirty | 20
> vacuum_cost_page_hit | 1
> vacuum_cost_page_miss | 10
> vacuum_defer_cleanup_age | 0
> vacuum_freeze_min_age | 50000000
> vacuum_freeze_table_age | 150000000
> 
 

Re: Database transaction with intermittent slow responses

From
Gerardo Herzig
Date:
Oh, so *all* the transactions are being slowed down at that point...What about CPU IO Wait% at that moment? Could be
someother processes stressing the system out? 

Now im thinking about hard disk issues...maybe some "smart" messages?

Have some other hardware to give it a try?

Gerardo

----- Mensaje original -----
> De: "John Gorman" <jgorman@eldocomp.com>
> Para: "Gerardo Herzig" <gherzig@fmed.uba.ar>
> CC: pgsql-performance@postgresql.org, "John Gorman" <jgorman@eldocomp.com>
> Enviados: Viernes, 13 de Mayo 2016 18:25:37
> Asunto: RE: [PERFORM] Database transaction with intermittent slow responses
>
> Hi Gerado,
>
> Thanks for the quick response. We do not appear to have a connection
> limit since our application is the only thing talking to the
> database, the connections are somewhat limited. We are using about
> 126 of a max allowed 350 connections. We keep these metrics in a
> different database, and we also generate alerts if we get close to
> the catalog/cluster limit.
>
> Also I have been monitoring heavily and watching for locks while the
> transaction runs for a long time. While I see occasional locks, they
> are on other tables and are brief, so I do not believe there is a
> database lock issue/contention.
>
> The application is timing the transaction out. When we detect that
> the timeout limit has occurred, we cancel the database connection
> (conn.cancel();) - we have been doing this for several years with no
> issue.
>
> I setup a adhoc monitor which runs every 2 seconds and displays
> "select * from pg_stat_activity where datname = 'p306' and
> current_query not like '<IDLE%'; and then write the output to a log.
> I can see the transaction being executed in the database for over 50
> seconds, so I do believe the database actually is working on it.
>
> We have a few monitoring programs that track and record quite a few
> thinks including database locks (number and type), connections
> (number and where). I have reviewed the history and do not see any
> trends.
>
> If it helps here is a monitor snippet of the transaction taking over
> 50 seconds (SELECT * FROM ChangeHistory)
>
>
> >> Wed May 11 07:50:09 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>
> >> Wed May 11 07:50:11 MST 2016
>  3709009 | p306    |   15014 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       35859
>  | 2016-05-11 07:31:31.968087-07 | 2016-05-11 07:50:11.575881-07 |
>  2016-05-11 07:50:11.766942-07 | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:11.712848-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:11.712887-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:13 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:13.733643-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:13.770366-07 |
>  2016-05-11 07:50:13.811502-07 | f       | SELECT * FROM Dependent
>  WHERE DependentID = $1
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:13.733968-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:15 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:15.734777-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:15.73486-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:17 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>
> >> Wed May 11 07:50:19 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>
> >> Wed May 11 07:50:21 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   21656 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       41810 |
>  2016-05-11 07:48:40.95846-07  | 2016-05-11 07:50:21.871077-07 |
>  2016-05-11 07:50:21.871579-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |    8042 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       63023 |
>  2016-05-11 07:14:34.208098-07 | 2016-05-11 07:50:21.813662-07 |
>  2016-05-11 07:50:21.814575-07 | f       | SELECT * FROM Employee
>  WHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>
> >> Wed May 11 07:50:23 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306     |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306     |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:23.85706-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    7925 |    16387 | p306     |
>                   | 172.20.0.82 | coreb               |       62888
>  | 2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 |
>  2016-05-11 07:50:23.684134-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |    8671 |    16387 | p306     |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:23.857092-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   22235 |       10 | postgres |
>                   |             |                     |
>              | 2016-05-11 07:50:22.129887-07 | 2016-05-11
>  07:50:22.162326-07 | 2016-05-11 07:50:22.162326-07 | f       |
>  autovacuum: VACUUM public.adjrespendrsncode
>
> >> Wed May 11 07:50:25 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    7925 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       62888
>  | 2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 |
>  2016-05-11 07:50:25.931788-07 | f       | SELECT * FROM
>  CategoryPlaceService WHERE CategoryID = $1 ORDER BY CategoryID,
>  RangeFrom, RangeTo LIMIT 1000
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:25.920308-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:27 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:27.935677-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:27.938329-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:29 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17652 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38402
>  | 2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:29.615446-07 |
>  2016-05-11 07:50:29.954405-07 | f       | SELECT * FROM Dependent
>  WHERE DepSocialSecurityNumber BETWEEN $1 AND $2 ORDER BY
>  DepCertificateNumber, DepSocialSecurityNumber, DepLastName,
>  DepFirstName, DepMiddleName, DepMedicareID, BirthDate,
>  AlternateID1, AlternateID2 LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:29.966428-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:29.966481-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:31 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:32.000148-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:34 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:33.953492-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:33.953803-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:36 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:35.996862-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:35.996892-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:38 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:38.039441-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:38.036922-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:40 MST 2016
>  3709009 | p306    |   17321 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38226
>  | 2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:40.059438-07 |
>  2016-05-11 07:50:40.060951-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:40.060863-07 |
>  2016-05-11 07:50:40.062051-07 | f       | SELECT * FROM Employee
>  WHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |   17652 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38402
>  | 2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:40.059956-07 |
>  2016-05-11 07:50:40.083659-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:40.077061-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:40.060076-07 |
>  2016-05-11 07:50:40.072735-07 | f       | INSERT INTO CrmCallLinks
>  VALUES
>  ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27)
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:40.080967-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   18895 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       39389
>  | 2016-05-11 07:42:04.682022-07 | 2016-05-11 07:50:40.062356-07 |
>  2016-05-11 07:50:40.062667-07 | f       | SELECT * FROM
>  RealtimeTransInfo WHERE SenderID = $1 AND PayLoadID = $2 ORDER BY
>  SenderID DESC, PayLoadID DESC LIMIT 2
>  3709009 | p306    |    8864 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       64407
>  | 2016-05-11 07:18:34.848657-07 | 2016-05-11 07:50:39.601078-07 |
>  2016-05-11 07:50:40.077433-07 | f       | SELECT * FROM Facility
>  WHERE FacilityID = $1
>
> >> Wed May 11 07:50:42 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:42.094681-07 |
>  2016-05-11 07:50:42.095179-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:42.023507-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:42.023043-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:44 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:44.054554-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:44.054674-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:46 MST 2016
>  3709009 | p306    |   17321 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38226
>  | 2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:45.908151-07 |
>  2016-05-11 07:50:46.08959-07  | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:46.077355-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:46.139211-07 |
>  2016-05-11 07:50:46.141386-07 | f       | SELECT * FROM
>  AdjudicationResult WHERE Claimnumber BETWEEN $1 AND $2 ORDER BY
>  Claimnumber DESC LIMIT 11
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:46.067222-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:48 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:48.082695-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:48.082883-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:50 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:50.056892-07 |
>  2016-05-11 07:50:50.174587-07 | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:50.107102-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    5620 |    16387 | p306    | TaskRunner
>        | 172.20.0.86 | batchb.eldocomp.com |       37594 |
>  2016-05-11 07:04:08.129626-07 | 2016-05-11 07:50:49.812093-07 |
>  2016-05-11 07:50:49.81238-07  | f       | SELECT * FROM
>  EDIFtpFileDetails WHERE MsgLogStatus = $1 AND ProcessId > $2 ORDER
>  BY MsgLogStatus, ProcessId LIMIT 10
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:50.107172-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:52 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:52.127455-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:52.127776-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:54 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:54.165381-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:54.165596-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:56 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:56.189515-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:56.176308-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:50:58 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   21656 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       41810
>  | 2016-05-11 07:48:40.95846-07  | 2016-05-11 07:50:56.785032-07 |
>  2016-05-11 07:50:56.789767-07 | f       | SELECT * FROM
>  FacilityPhysicianAffl WHERE  Status IN ('A', 'H', 'D') AND
>  (FacilityID IN (SELECT FacilityID FROM Facility WHERE UPPER(TaxID)=
>  '811190101' AND Status IN (  'A' ,  'H' ,  'D')  ) AND  (
>  PhysicianID IN (SELECT PhysicianID FROM Physician WHERE Status IN (
>   'A' ,  'H' ,  'D')  )) AND (( ISDUMMY='0' AND FacilityID IN (
>  SELECT FacilityID FROM Facility WHERE FacilityRecordType = 'S' AND
>   ( FacilityName IS NOT NULL AND FacilityName != '' ) )  OR (
>  FacilityID IN ( SELECT FacilityID FROM Facility WHERE
>  FacilityRecordType = 'F' AND  ( FacilityName IS NOT NULL AND
>  FacilityName != '' ) ))))) ORDER BY FacilityID ASC , PhysicianID
>  ASC
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:58.212226-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:58.269389-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:51:00 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:00.228846-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:00.229019-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:51:02 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    4715 |    16387 | p306    | TaskRunner
>        | 172.20.0.86 | batchb.eldocomp.com |       33881 |
>  2016-05-11 07:01:41.247388-07 | 2016-05-11 07:51:02.125906-07 |
>  2016-05-11 07:51:02.311956-07 | f       | SELECT * FROM
>  EmpEligibilityCoverage WHERE EmployeeID = $1 AND EffectiveDate <=
>  $2 ORDER BY EmployeeID DESC, EffectiveDate DESC LIMIT 101
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:02.23586-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:51:02.188886-07 |
>  2016-05-11 07:51:02.295888-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:02.235869-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:51:04 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:04.277287-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:04.277543-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:51:06 MST 2016
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:06.313649-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:06.313855-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> >> Wed May 11 07:51:08 MST 2016
>  3709009 | p306    |   22530 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       42494
>  | 2016-05-11 07:51:04.419169-07 | 2016-05-11 07:51:08.351721-07 |
>  2016-05-11 07:51:08.373929-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category = $1 AND PrimaryKeyOfChange = $2 ORDER
>  BY Category, PrimaryKeyOfChange, ChgTS, ExcludedKeyFields LIMIT
>  2001
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:08.335854-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:08.359281-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>
> Regards
> John
>
> -----Original Message-----
> From: Gerardo Herzig [mailto:gherzig@fmed.uba.ar]
> Sent: Friday, May 13, 2016 2:05 PM
> To: John Gorman
> Cc: pgsql-performance@postgresql.org
> Subject: Re: [PERFORM] Database transaction with intermittent slow
> responses
>
> After quick reading, im thinking about a couples of chances:
>
> 1) You are hitting a connection_limit
> 2) You are hitting a lock contention (perhaps some other backend is
> locking the table and not releasing it)
>
> Who throws the timeout? It is Postgres or your JDBC connector?
>
> My initial blind guess is that your "timed out queries" never gets
> postgres at all, and are blocked prior to that for some other issue.
> If im wrong, well, you should at least have the timeout recorded in
> your logs.
>
> You should also track #of_connectinos and #of_locks over that tables.
>
> See http://www.postgresql.org/docs/9.1/static/view-pg-locks.html for
> pg_lock information
>
> That should be my starting point for viewing whats going on.
>
> HTH
> Gerardo
>
> ----- Mensaje original -----
> > De: "John Gorman" <jgorman@eldocomp.com>
> > Para: pgsql-performance@postgresql.org
> > CC: "John Gorman" <jgorman@eldocomp.com>
> > Enviados: Viernes, 13 de Mayo 2016 16:59:51
> > Asunto: [PERFORM] Database transaction with intermittent slow
> > responses
> >
> >
> > Transactions to table, ChangeHistory, have recently become
> > intermittently slow and is increasing becoming slower.
> >
> > * No database configuration changes have been made recently
> > * We have run vacuum analyze
> > * We have tried backing up and reloading the table (data, indexes,
> > etc)
> >
> > Some transactions respond quickly (200 ms) and others take over 55
> > seconds (we cancel the query after 55 seconds – our timeout SLA).
> > The problem has recently become very bad. It is the same query
> > being
> > issued but with different parameters.
> >
> > If the transaction takes over 55 seconds and I run the query
> > manually
> > (with or without EXPLAIN ANALYZE) it returns quickly (a few hundred
> > ms). In case I am looking at cache, I have a list of other queries
> > (just different parameters) that have timed out and when I run them
> > (without the limit even) the response is very timely.
> >
> > Any help or insight would be great.
> >
> > NOTE: our application is connecting to the database via JDBC and we
> > are using PreparedStatements. I have provided full details so all
> > information is available, but please let me know if any other
> > information is needed – thx in advance.
> >
> > p306=> EXPLAIN ANALYZE SELECT * FROM ChangeHistory WHERE Category
> > BETWEEN 'Employee' AND 'Employeezz' AND PrimaryKeyOfChange BETWEEN
> > '312313' AND '312313!zz' ORDER BY ChgTS DESC, ChgUser DESC,
> > Category
> > DESC, PrimaryKeyOfChange DESC LIMIT 11;
> > QUERY PLAN
> > ------------------------------------------------------------------------------------------------------
> > Limit (cost=33.66..33.67 rows=1 width=136) (actual
> > time=0.297..0.297
> > rows=11 loops=1)
> > -> Sort (cost=33.66..33.67 rows=1 width=136) (actual
> > time=0.297..0.297 rows=11 loops=1)
> > Sort Key: chgts, chguser, category, primarykeyofchange
> > Sort Method: top-N heapsort Memory: 27kB
> > -> Index Scan using changehistory_idx4 on changehistory
> > (cost=0.00..33.65 rows=1 width=136) (actual time=0.046..
> > 0.239 rows=85 loops=1)
> > Index Cond: (((primarykeyofchange)::text >= '312313'::text) AND
> > ((primarykeyofchange)::text <= '312313!zz'::
> > text))
> > Filter: (((category)::text >= 'Employee'::text) AND
> > ((category)::text
> > <= 'Employeezz'::text))
> > Total runtime: 0.328 ms
> > (8 rows)
> >
> > >>>
> > History this week of counts with good response times vs timeouts.
> >
> > | Date | Success # | Time Out # | Avg. Success Secs |
> > |------------+-----------+------------+-------------------|
> > | 2016-05-09 | 18 | 31 | 7.9 |
> > | 2016-05-10 | 17 | 25 | 10.5 |
> > | 2016-05-11 | 27 | 33 | 10.1 |
> > | 2016-05-12 | 68 | 24 | 9.9 |
> >
> >
> > >>> Sample transaction response times
> >
> > | Timestamp | Tran ID | Resp MS | Resp CD
> > --------------------+----------------+---------+--------
> > 2016-05-10 06:20:19 | ListChangeHist | 55,023 | TIMEOUT
> > 2016-05-10 07:47:34 | ListChangeHist | 55,017 | TIMEOUT
> > 2016-05-10 07:48:00 | ListChangeHist | 9,866 | OK
> > 2016-05-10 07:48:10 | ListChangeHist | 2,327 | OK
> > 2016-05-10 07:59:23 | ListChangeHist | 55,020 | TIMEOUT
> > 2016-05-10 08:11:20 | ListChangeHist | 55,030 | TIMEOUT
> > 2016-05-10 08:31:45 | ListChangeHist | 4,216 | OK
> > 2016-05-10 08:35:09 | ListChangeHist | 7,898 | OK
> > 2016-05-10 08:36:18 | ListChangeHist | 9,810 | OK
> > 2016-05-10 08:36:56 | ListChangeHist | 55,027 | TIMEOUT
> > 2016-05-10 08:37:33 | ListChangeHist | 46,433 | OK
> > 2016-05-10 08:38:09 | ListChangeHist | 55,019 | TIMEOUT
> > 2016-05-10 08:53:43 | ListChangeHist | 55,019 | TIMEOUT
> > 2016-05-10 09:45:09 | ListChangeHist | 55,022 | TIMEOUT
> > 2016-05-10 09:46:13 | ListChangeHist | 55,017 | TIMEOUT
> > 2016-05-10 09:49:27 | ListChangeHist | 55,011 | TIMEOUT
> > 2016-05-10 09:52:12 | ListChangeHist | 55,018 | TIMEOUT
> > 2016-05-10 09:57:42 | ListChangeHist | 9,462 | OK
> > 2016-05-10 10:05:21 | ListChangeHist | 55,016 | TIMEOUT
> > 2016-05-10 10:05:29 | ListChangeHist | 136 | OK
> > 2016-05-10 10:05:38 | ListChangeHist | 1,517 | OK
> >
> > Artifacts
> > ======================
> >
> > $ >uname -a
> > SunOS ***** 5.10 Generic_150400-30 sun4v sparc sun4v
> >
> > Memory : 254G phys mem, 207G free mem.
> > Processors: 32 - CPU is mostly 80% free
> >
> > >>>
> > p306=> select version();
> > version
> > ---------------------------------------------------------------------------------------------------
> > PostgreSQL 9.1.14 on sparc-sun-solaris2.10, compiled by gcc (GCC)
> > 3.4.3 (csl-sol210-3_4-branch+sol_rpath), 64-bit
> >
> > >>>
> > p306=> \dt+ changehistory
> > List of relations
> > Schema | Name | Type | Owner | Size | Description
> > --------+---------------+-------+-------+-------+-------------
> > public | changehistory | table | p306 | 17 GB |
> >
> > >>>
> > p306=> \di+ changehistory*
> > List of relations
> > Schema | Name | Type | Owner | Table | Size | Description
> > --------+-----------------------+-------+-------+---------------+---------+-------------
> > public | changehistory_idx1 | index | p306 | changehistory | 9597
> > MB
> > |
> > public | changehistory_idx3 | index | p306 | changehistory | 11 GB
> > |
> > public | changehistory_idx4 | index | p306 | changehistory | 4973
> > MB
> > |
> > public | changehistory_pkey | index | p306 | changehistory | 2791
> > MB
> > |
> > public | changehistory_search2 | index | p306 | changehistory |
> > 9888
> > MB |
> > public | changehistory_search3 | index | p306 | changehistory | 10
> > GB
> > |
> > public | changehistory_search4 | index | p306 | changehistory |
> > 9240
> > MB |
> > public | changehistory_search5 | index | p306 | changehistory |
> > 8373
> > MB |
> > (8 rows)
> >
> >
> > >>>
> > p306=> select count(*) from changehistory ;
> > count
> > ------------
> > 129,185,024
> >
> > >>>
> > Show all (filtered)
> > ======================================================
> >
> > name | setting
> > ---------------------------------+--------------------
> > autovacuum | on
> > autovacuum_analyze_scale_factor | 0.001
> > autovacuum_analyze_threshold | 500
> > autovacuum_freeze_max_age | 200000000
> > autovacuum_max_workers | 5
> > autovacuum_naptime | 1min
> > autovacuum_vacuum_cost_delay | 0
> > autovacuum_vacuum_cost_limit | -1
> > autovacuum_vacuum_scale_factor | 0.001
> > autovacuum_vacuum_threshold | 500
> > bgwriter_delay | 200ms
> > block_size | 8192
> > check_function_bodies | on
> > checkpoint_completion_target | 0.9
> > checkpoint_segments | 256
> > checkpoint_timeout | 1h
> > checkpoint_warning | 30s
> > client_encoding | UTF8
> > commit_delay | 0
> > commit_siblings | 5
> > cpu_index_tuple_cost | 0.005
> > cpu_operator_cost | 0.0025
> > cpu_tuple_cost | 0.01
> > cursor_tuple_fraction | 0.1
> > deadlock_timeout | 1s
> > default_statistics_target | 100
> > default_transaction_deferrable | off
> > default_transaction_isolation | read committed
> > default_transaction_read_only | off
> > default_with_oids | off
> > effective_cache_size | 8GB
> > from_collapse_limit | 8
> > fsync | on
> > full_page_writes | on
> > ignore_system_indexes | off
> > join_collapse_limit | 8
> > krb_caseins_users | off
> > lo_compat_privileges | off
> > maintenance_work_mem | 1GB
> > max_connections | 350
> > max_files_per_process | 1000
> > max_function_args | 100
> > max_identifier_length | 63
> > max_index_keys | 32
> > max_locks_per_transaction | 64
> > max_pred_locks_per_transaction | 64
> > max_prepared_transactions | 0
> > max_stack_depth | 2MB
> > max_wal_senders | 5
> > random_page_cost | 4
> > segment_size | 1GB
> > seq_page_cost | 1
> > server_encoding | UTF8
> > server_version | 9.1.14
> > shared_buffers | 2GB
> > sql_inheritance | on
> > statement_timeout | 0
> > synchronize_seqscans | on
> > synchronous_commit | on
> > synchronous_standby_names |
> > tcp_keepalives_count | 0
> > tcp_keepalives_idle | -1
> > tcp_keepalives_interval | 0
> > track_activities | on
> > track_activity_query_size | 1024
> > track_counts | on
> > track_functions | none
> > transaction_deferrable | off
> > transaction_isolation | read committed
> > transaction_read_only | off
> > transform_null_equals | off
> > update_process_title | on
> > vacuum_cost_delay | 0
> > vacuum_cost_limit | 200
> > vacuum_cost_page_dirty | 20
> > vacuum_cost_page_hit | 1
> > vacuum_cost_page_miss | 10
> > vacuum_defer_cleanup_age | 0
> > vacuum_freeze_min_age | 50000000
> > vacuum_freeze_table_age | 150000000
> >
>
>


Re: Database transaction with intermittent slow responses

From
Robert Klemme
Date:
On Sat, May 14, 2016 at 1:11 AM, Gerardo Herzig wrote:
> Oh, so *all* the transactions are being slowed down at that point...What about CPU IO Wait% at that moment? Could be
someother processes stressing the system out? 

Or the database has just grown pass the size where disk caching is
efficient. Usually these are nonlinear processes, i.e. it works good
until a certain moment and then cache hit ratio decreases dramatically
because all of a sudden content starts heavily competing about space
in the cache.

> Now im thinking about hard disk issues...maybe some "smart" messages?
>
> Have some other hardware to give it a try?

Can we please see the full DDL of table and indexes?

The only additional idea I can throw up at the moment is looking at a
combined index on (primarykeyofchange, category) - maybe replacing
changehistory_idx4 - but that of course depends on the other SQL used
against that table.

Kind regards

robert

--
[guy, jim, charlie].each {|him| remember.him do |as, often| as.you_can
- without end}
http://blog.rubybestpractices.com/


Re: Database transaction with intermittent slow responses

From
John Gorman
Date:
Hi Gerado and Robert,

We turned DEBUG on in the application logs and then this weekend I was going to multi-threaded test program to
reproducethe issue in a stand-alone program, and when I got the debug logs and stripped out everything except the
databasequeries for the ChangeHistory table, I found some other unexpected transactions which were hitting the
ChangeHistorytable fairly hard and in rapid succession.
 

At this point development is looking into it, and we believe this application transaction is the source of the issue,
whichis why I have not responded to your emails.
 

I should know more after tonight.

Thanks again for your feedback and responses

Regards
John

-----Original Message-----
From: Gerardo Herzig [mailto:gherzig@fmed.uba.ar] 
Sent: Friday, May 13, 2016 4:11 PM
To: John Gorman
Cc: pgsql-performance@postgresql.org
Subject: Re: [PERFORM] Database transaction with intermittent slow responses

Oh, so *all* the transactions are being slowed down at that point...What about CPU IO Wait% at that moment? Could be
someother processes stressing the system out?
 

Now im thinking about hard disk issues...maybe some "smart" messages?

Have some other hardware to give it a try?

Gerardo

----- Mensaje original -----
> De: "John Gorman" <jgorman@eldocomp.com>
> Para: "Gerardo Herzig" <gherzig@fmed.uba.ar>
> CC: pgsql-performance@postgresql.org, "John Gorman" <jgorman@eldocomp.com>
> Enviados: Viernes, 13 de Mayo 2016 18:25:37
> Asunto: RE: [PERFORM] Database transaction with intermittent slow responses
> 
> Hi Gerado,
> 
> Thanks for the quick response. We do not appear to have a connection
> limit since our application is the only thing talking to the
> database, the connections are somewhat limited. We are using about
> 126 of a max allowed 350 connections. We keep these metrics in a
> different database, and we also generate alerts if we get close to
> the catalog/cluster limit.
> 
> Also I have been monitoring heavily and watching for locks while the
> transaction runs for a long time. While I see occasional locks, they
> are on other tables and are brief, so I do not believe there is a
> database lock issue/contention.
> 
> The application is timing the transaction out. When we detect that
> the timeout limit has occurred, we cancel the database connection
> (conn.cancel();) - we have been doing this for several years with no
> issue.
> 
> I setup a adhoc monitor which runs every 2 seconds and displays
> "select * from pg_stat_activity where datname = 'p306' and
> current_query not like '<IDLE%'; and then write the output to a log.
> I can see the transaction being executed in the database for over 50
> seconds, so I do believe the database actually is working on it.
> 
> We have a few monitoring programs that track and record quite a few
> thinks including database locks (number and type), connections
> (number and where). I have reviewed the history and do not see any
> trends.
> 
> If it helps here is a monitor snippet of the transaction taking over
> 50 seconds (SELECT * FROM ChangeHistory)
> 
> 
> >> Wed May 11 07:50:09 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
> 
> >> Wed May 11 07:50:11 MST 2016
>  3709009 | p306    |   15014 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       35859
>  | 2016-05-11 07:31:31.968087-07 | 2016-05-11 07:50:11.575881-07 |
>  2016-05-11 07:50:11.766942-07 | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:11.712848-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:11.712887-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:13 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:13.733643-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:13.770366-07 |
>  2016-05-11 07:50:13.811502-07 | f       | SELECT * FROM Dependent
>  WHERE DependentID = $1
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:13.733968-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:15 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:15.734777-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:15.73486-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:17 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
> 
> >> Wed May 11 07:50:19 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
> 
> >> Wed May 11 07:50:21 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       59871 |
>  2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   21656 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       41810 |
>  2016-05-11 07:48:40.95846-07  | 2016-05-11 07:50:21.871077-07 |
>  2016-05-11 07:50:21.871579-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |    8042 |    16387 | p306    |
>                   | 172.20.0.82 | coreb           |       63023 |
>  2016-05-11 07:14:34.208098-07 | 2016-05-11 07:50:21.813662-07 |
>  2016-05-11 07:50:21.814575-07 | f       | SELECT * FROM Employee
>  WHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
> 
> >> Wed May 11 07:50:23 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306     |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306     |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:23.85706-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    7925 |    16387 | p306     |
>                   | 172.20.0.82 | coreb               |       62888
>  | 2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 |
>  2016-05-11 07:50:23.684134-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |    8671 |    16387 | p306     |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:23.857092-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   22235 |       10 | postgres |
>                   |             |                     |
>              | 2016-05-11 07:50:22.129887-07 | 2016-05-11
>  07:50:22.162326-07 | 2016-05-11 07:50:22.162326-07 | f       |
>  autovacuum: VACUUM public.adjrespendrsncode
> 
> >> Wed May 11 07:50:25 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    7925 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       62888
>  | 2016-05-11 07:14:05.586327-07 | 2016-05-11 07:50:23.517469-07 |
>  2016-05-11 07:50:25.931788-07 | f       | SELECT * FROM
>  CategoryPlaceService WHERE CategoryID = $1 ORDER BY CategoryID,
>  RangeFrom, RangeTo LIMIT 1000
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:25.920308-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:27 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:27.935677-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:27.938329-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:29 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17652 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38402
>  | 2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:29.615446-07 |
>  2016-05-11 07:50:29.954405-07 | f       | SELECT * FROM Dependent
>  WHERE DepSocialSecurityNumber BETWEEN $1 AND $2 ORDER BY
>  DepCertificateNumber, DepSocialSecurityNumber, DepLastName,
>  DepFirstName, DepMiddleName, DepMedicareID, BirthDate,
>  AlternateID1, AlternateID2 LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:29.966428-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:29.966481-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:31 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:32.000148-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:34 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:33.953492-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:33.953803-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:36 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:35.996862-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:35.996892-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:38 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:38.039441-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:38.036922-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:40 MST 2016
>  3709009 | p306    |   17321 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38226
>  | 2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:40.059438-07 |
>  2016-05-11 07:50:40.060951-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:40.060863-07 |
>  2016-05-11 07:50:40.062051-07 | f       | SELECT * FROM Employee
>  WHERE CertificateNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |   17652 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38402
>  | 2016-05-11 07:39:00.298771-07 | 2016-05-11 07:50:40.059956-07 |
>  2016-05-11 07:50:40.083659-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:40.077061-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:40.060076-07 |
>  2016-05-11 07:50:40.072735-07 | f       | INSERT INTO CrmCallLinks
>  VALUES
>  ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27)
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:40.080967-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   18895 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       39389
>  | 2016-05-11 07:42:04.682022-07 | 2016-05-11 07:50:40.062356-07 |
>  2016-05-11 07:50:40.062667-07 | f       | SELECT * FROM
>  RealtimeTransInfo WHERE SenderID = $1 AND PayLoadID = $2 ORDER BY
>  SenderID DESC, PayLoadID DESC LIMIT 2
>  3709009 | p306    |    8864 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       64407
>  | 2016-05-11 07:18:34.848657-07 | 2016-05-11 07:50:39.601078-07 |
>  2016-05-11 07:50:40.077433-07 | f       | SELECT * FROM Facility
>  WHERE FacilityID = $1
> 
> >> Wed May 11 07:50:42 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:42.094681-07 |
>  2016-05-11 07:50:42.095179-07 | f       | DELETE FROM
>  ClaimPrevQueue WHERE Claimnumber = $1
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:42.023507-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:42.023043-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:44 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:44.054554-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:44.054674-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:46 MST 2016
>  3709009 | p306    |   17321 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       38226
>  | 2016-05-11 07:38:10.838611-07 | 2016-05-11 07:50:45.908151-07 |
>  2016-05-11 07:50:46.08959-07  | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:46.077355-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:50:46.139211-07 |
>  2016-05-11 07:50:46.141386-07 | f       | SELECT * FROM
>  AdjudicationResult WHERE Claimnumber BETWEEN $1 AND $2 ORDER BY
>  Claimnumber DESC LIMIT 11
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:46.067222-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:48 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:48.082695-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:48.082883-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:50 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    2860 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       56427
>  | 2016-05-11 06:53:47.633683-07 | 2016-05-11 07:50:50.056892-07 |
>  2016-05-11 07:50:50.174587-07 | f       | SELECT * FROM Employee
>  WHERE SocialSecurityNumber BETWEEN $1 AND $2 ORDER BY LastName,
>  FirstName, MiddleName, BlkOfBusID, ClientID, CertificateNumber,
>  SocialSecurityNumber, MedicareID, BirthDate, AlternateID1,
>  AlternateID2 LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:50.107102-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    5620 |    16387 | p306    | TaskRunner
>        | 172.20.0.86 | batchb.eldocomp.com |       37594 |
>  2016-05-11 07:04:08.129626-07 | 2016-05-11 07:50:49.812093-07 |
>  2016-05-11 07:50:49.81238-07  | f       | SELECT * FROM
>  EDIFtpFileDetails WHERE MsgLogStatus = $1 AND ProcessId > $2 ORDER
>  BY MsgLogStatus, ProcessId LIMIT 10
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:50.107172-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:52 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:52.127455-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:52.127776-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:54 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:54.165381-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:54.165596-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:56 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:56.189515-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:56.176308-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:50:58 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   21656 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       41810
>  | 2016-05-11 07:48:40.95846-07  | 2016-05-11 07:50:56.785032-07 |
>  2016-05-11 07:50:56.789767-07 | f       | SELECT * FROM
>  FacilityPhysicianAffl WHERE  Status IN ('A', 'H', 'D') AND
>  (FacilityID IN (SELECT FacilityID FROM Facility WHERE UPPER(TaxID)=
>  '811190101' AND Status IN (  'A' ,  'H' ,  'D')  ) AND  (
>  PhysicianID IN (SELECT PhysicianID FROM Physician WHERE Status IN (
>   'A' ,  'H' ,  'D')  )) AND (( ISDUMMY='0' AND FacilityID IN (
>  SELECT FacilityID FROM Facility WHERE FacilityRecordType = 'S' AND
>   ( FacilityName IS NOT NULL AND FacilityName != '' ) )  OR (
>  FacilityID IN ( SELECT FacilityID FROM Facility WHERE
>  FacilityRecordType = 'F' AND  ( FacilityName IS NOT NULL AND
>  FacilityName != '' ) ))))) ORDER BY FacilityID ASC , PhysicianID
>  ASC
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:50:58.212226-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:50:58.269389-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:51:00 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:00.228846-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:00.229019-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:51:02 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |    4715 |    16387 | p306    | TaskRunner
>        | 172.20.0.86 | batchb.eldocomp.com |       33881 |
>  2016-05-11 07:01:41.247388-07 | 2016-05-11 07:51:02.125906-07 |
>  2016-05-11 07:51:02.311956-07 | f       | SELECT * FROM
>  EmpEligibilityCoverage WHERE EmployeeID = $1 AND EffectiveDate <=
>  $2 ORDER BY EmployeeID DESC, EffectiveDate DESC LIMIT 101
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:02.23586-07  | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |   16771 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       37470
>  | 2016-05-11 07:36:18.535139-07 | 2016-05-11 07:51:02.188886-07 |
>  2016-05-11 07:51:02.295888-07 | f       | DELETE FROM
>  ToothChartMaintenance WHERE Claimnumber = $1
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:02.235869-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:51:04 MST 2016
>  3709009 | p306    |    5644 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       59871
>  | 2016-05-11 07:04:16.503194-07 | 2016-05-11 07:50:09.394202-07 |
>  2016-05-11 07:50:09.396161-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category BETWEEN $1 AND $2 AND
>  PrimaryKeyOfChange BETWEEN $3 AND $4 ORDER BY ChgTS DESC, ChgUser
>  DESC, Category DESC, PrimaryKeyOfChange DESC LIMIT 11
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:04.277287-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:04.277543-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:51:06 MST 2016
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:06.313649-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:06.313855-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> >> Wed May 11 07:51:08 MST 2016
>  3709009 | p306    |   22530 |    16387 | p306    |
>                   | 172.20.0.82 | coreb               |       42494
>  | 2016-05-11 07:51:04.419169-07 | 2016-05-11 07:51:08.351721-07 |
>  2016-05-11 07:51:08.373929-07 | f       | SELECT * FROM
>  ChangeHistory WHERE Category = $1 AND PrimaryKeyOfChange = $2 ORDER
>  BY Category, PrimaryKeyOfChange, ChgTS, ExcludedKeyFields LIMIT
>  2001
>  3709009 | p306    |   17312 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       54263
>  | 2016-05-11 07:38:08.464797-07 | 2016-05-11 07:47:42.982944-07 |
>  2016-05-11 07:51:08.335854-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
>  3709009 | p306    |    8671 |    16387 | p306    |
>                   | 172.20.0.86 | batchb.eldocomp.com |       55055
>  | 2016-05-11 07:17:52.292909-07 | 2016-05-11 07:40:50.525528-07 |
>  2016-05-11 07:51:08.359281-07 | f       | SELECT * FROM Employee
>  WHERE EmployeeID BETWEEN $1 AND $2 ORDER BY EmployeeID LIMIT 1001
> 
> Regards
> John
> 
> -----Original Message-----
> From: Gerardo Herzig [mailto:gherzig@fmed.uba.ar]
> Sent: Friday, May 13, 2016 2:05 PM
> To: John Gorman
> Cc: pgsql-performance@postgresql.org
> Subject: Re: [PERFORM] Database transaction with intermittent slow
> responses
> 
> After quick reading, im thinking about a couples of chances:
> 
> 1) You are hitting a connection_limit
> 2) You are hitting a lock contention (perhaps some other backend is
> locking the table and not releasing it)
> 
> Who throws the timeout? It is Postgres or your JDBC connector?
> 
> My initial blind guess is that your "timed out queries" never gets
> postgres at all, and are blocked prior to that for some other issue.
> If im wrong, well, you should at least have the timeout recorded in
> your logs.
> 
> You should also track #of_connectinos and #of_locks over that tables.
> 
> See http://www.postgresql.org/docs/9.1/static/view-pg-locks.html for
> pg_lock information
> 
> That should be my starting point for viewing whats going on.
> 
> HTH
> Gerardo
> 
> ----- Mensaje original -----
> > De: "John Gorman" <jgorman@eldocomp.com>
> > Para: pgsql-performance@postgresql.org
> > CC: "John Gorman" <jgorman@eldocomp.com>
> > Enviados: Viernes, 13 de Mayo 2016 16:59:51
> > Asunto: [PERFORM] Database transaction with intermittent slow
> > responses
> > 
> > 
> > Transactions to table, ChangeHistory, have recently become
> > intermittently slow and is increasing becoming slower.
> > 
> > * No database configuration changes have been made recently
> > * We have run vacuum analyze
> > * We have tried backing up and reloading the table (data, indexes,
> > etc)
> > 
> > Some transactions respond quickly (200 ms) and others take over 55
> > seconds (we cancel the query after 55 seconds – our timeout SLA).
> > The problem has recently become very bad. It is the same query
> > being
> > issued but with different parameters.
> > 
> > If the transaction takes over 55 seconds and I run the query
> > manually
> > (with or without EXPLAIN ANALYZE) it returns quickly (a few hundred
> > ms). In case I am looking at cache, I have a list of other queries
> > (just different parameters) that have timed out and when I run them
> > (without the limit even) the response is very timely.
> > 
> > Any help or insight would be great.
> > 
> > NOTE: our application is connecting to the database via JDBC and we
> > are using PreparedStatements. I have provided full details so all
> > information is available, but please let me know if any other
> > information is needed – thx in advance.
> > 
> > p306=> EXPLAIN ANALYZE SELECT * FROM ChangeHistory WHERE Category
> > BETWEEN 'Employee' AND 'Employeezz' AND PrimaryKeyOfChange BETWEEN
> > '312313' AND '312313!zz' ORDER BY ChgTS DESC, ChgUser DESC,
> > Category
> > DESC, PrimaryKeyOfChange DESC LIMIT 11;
> > QUERY PLAN
> > ------------------------------------------------------------------------------------------------------
> > Limit (cost=33.66..33.67 rows=1 width=136) (actual
> > time=0.297..0.297
> > rows=11 loops=1)
> > -> Sort (cost=33.66..33.67 rows=1 width=136) (actual
> > time=0.297..0.297 rows=11 loops=1)
> > Sort Key: chgts, chguser, category, primarykeyofchange
> > Sort Method: top-N heapsort Memory: 27kB
> > -> Index Scan using changehistory_idx4 on changehistory
> > (cost=0.00..33.65 rows=1 width=136) (actual time=0.046..
> > 0.239 rows=85 loops=1)
> > Index Cond: (((primarykeyofchange)::text >= '312313'::text) AND
> > ((primarykeyofchange)::text <= '312313!zz'::
> > text))
> > Filter: (((category)::text >= 'Employee'::text) AND
> > ((category)::text
> > <= 'Employeezz'::text))
> > Total runtime: 0.328 ms
> > (8 rows)
> > 
> > >>> 
> > History this week of counts with good response times vs timeouts.
> > 
> > | Date | Success # | Time Out # | Avg. Success Secs |
> > |------------+-----------+------------+-------------------|
> > | 2016-05-09 | 18 | 31 | 7.9 |
> > | 2016-05-10 | 17 | 25 | 10.5 |
> > | 2016-05-11 | 27 | 33 | 10.1 |
> > | 2016-05-12 | 68 | 24 | 9.9 |
> > 
> > 
> > >>> Sample transaction response times
> > 
> > | Timestamp | Tran ID | Resp MS | Resp CD
> > --------------------+----------------+---------+--------
> > 2016-05-10 06:20:19 | ListChangeHist | 55,023 | TIMEOUT
> > 2016-05-10 07:47:34 | ListChangeHist | 55,017 | TIMEOUT
> > 2016-05-10 07:48:00 | ListChangeHist | 9,866 | OK
> > 2016-05-10 07:48:10 | ListChangeHist | 2,327 | OK
> > 2016-05-10 07:59:23 | ListChangeHist | 55,020 | TIMEOUT
> > 2016-05-10 08:11:20 | ListChangeHist | 55,030 | TIMEOUT
> > 2016-05-10 08:31:45 | ListChangeHist | 4,216 | OK
> > 2016-05-10 08:35:09 | ListChangeHist | 7,898 | OK
> > 2016-05-10 08:36:18 | ListChangeHist | 9,810 | OK
> > 2016-05-10 08:36:56 | ListChangeHist | 55,027 | TIMEOUT
> > 2016-05-10 08:37:33 | ListChangeHist | 46,433 | OK
> > 2016-05-10 08:38:09 | ListChangeHist | 55,019 | TIMEOUT
> > 2016-05-10 08:53:43 | ListChangeHist | 55,019 | TIMEOUT
> > 2016-05-10 09:45:09 | ListChangeHist | 55,022 | TIMEOUT
> > 2016-05-10 09:46:13 | ListChangeHist | 55,017 | TIMEOUT
> > 2016-05-10 09:49:27 | ListChangeHist | 55,011 | TIMEOUT
> > 2016-05-10 09:52:12 | ListChangeHist | 55,018 | TIMEOUT
> > 2016-05-10 09:57:42 | ListChangeHist | 9,462 | OK
> > 2016-05-10 10:05:21 | ListChangeHist | 55,016 | TIMEOUT
> > 2016-05-10 10:05:29 | ListChangeHist | 136 | OK
> > 2016-05-10 10:05:38 | ListChangeHist | 1,517 | OK
> > 
> > Artifacts
> > ======================
> > 
> > $ >uname -a
> > SunOS ***** 5.10 Generic_150400-30 sun4v sparc sun4v
> > 
> > Memory : 254G phys mem, 207G free mem.
> > Processors: 32 - CPU is mostly 80% free
> > 
> > >>> 
> > p306=> select version();
> > version
> > ---------------------------------------------------------------------------------------------------
> > PostgreSQL 9.1.14 on sparc-sun-solaris2.10, compiled by gcc (GCC)
> > 3.4.3 (csl-sol210-3_4-branch+sol_rpath), 64-bit
> > 
> > >>> 
> > p306=> \dt+ changehistory
> > List of relations
> > Schema | Name | Type | Owner | Size | Description
> > --------+---------------+-------+-------+-------+-------------
> > public | changehistory | table | p306 | 17 GB |
> > 
> > >>> 
> > p306=> \di+ changehistory*
> > List of relations
> > Schema | Name | Type | Owner | Table | Size | Description
> > --------+-----------------------+-------+-------+---------------+---------+-------------
> > public | changehistory_idx1 | index | p306 | changehistory | 9597
> > MB
> > |
> > public | changehistory_idx3 | index | p306 | changehistory | 11 GB
> > |
> > public | changehistory_idx4 | index | p306 | changehistory | 4973
> > MB
> > |
> > public | changehistory_pkey | index | p306 | changehistory | 2791
> > MB
> > |
> > public | changehistory_search2 | index | p306 | changehistory |
> > 9888
> > MB |
> > public | changehistory_search3 | index | p306 | changehistory | 10
> > GB
> > |
> > public | changehistory_search4 | index | p306 | changehistory |
> > 9240
> > MB |
> > public | changehistory_search5 | index | p306 | changehistory |
> > 8373
> > MB |
> > (8 rows)
> > 
> > 
> > >>> 
> > p306=> select count(*) from changehistory ;
> > count
> > ------------
> > 129,185,024
> > 
> > >>> 
> > Show all (filtered)
> > ======================================================
> > 
> > name | setting
> > ---------------------------------+--------------------
> > autovacuum | on
> > autovacuum_analyze_scale_factor | 0.001
> > autovacuum_analyze_threshold | 500
> > autovacuum_freeze_max_age | 200000000
> > autovacuum_max_workers | 5
> > autovacuum_naptime | 1min
> > autovacuum_vacuum_cost_delay | 0
> > autovacuum_vacuum_cost_limit | -1
> > autovacuum_vacuum_scale_factor | 0.001
> > autovacuum_vacuum_threshold | 500
> > bgwriter_delay | 200ms
> > block_size | 8192
> > check_function_bodies | on
> > checkpoint_completion_target | 0.9
> > checkpoint_segments | 256
> > checkpoint_timeout | 1h
> > checkpoint_warning | 30s
> > client_encoding | UTF8
> > commit_delay | 0
> > commit_siblings | 5
> > cpu_index_tuple_cost | 0.005
> > cpu_operator_cost | 0.0025
> > cpu_tuple_cost | 0.01
> > cursor_tuple_fraction | 0.1
> > deadlock_timeout | 1s
> > default_statistics_target | 100
> > default_transaction_deferrable | off
> > default_transaction_isolation | read committed
> > default_transaction_read_only | off
> > default_with_oids | off
> > effective_cache_size | 8GB
> > from_collapse_limit | 8
> > fsync | on
> > full_page_writes | on
> > ignore_system_indexes | off
> > join_collapse_limit | 8
> > krb_caseins_users | off
> > lo_compat_privileges | off
> > maintenance_work_mem | 1GB
> > max_connections | 350
> > max_files_per_process | 1000
> > max_function_args | 100
> > max_identifier_length | 63
> > max_index_keys | 32
> > max_locks_per_transaction | 64
> > max_pred_locks_per_transaction | 64
> > max_prepared_transactions | 0
> > max_stack_depth | 2MB
> > max_wal_senders | 5
> > random_page_cost | 4
> > segment_size | 1GB
> > seq_page_cost | 1
> > server_encoding | UTF8
> > server_version | 9.1.14
> > shared_buffers | 2GB
> > sql_inheritance | on
> > statement_timeout | 0
> > synchronize_seqscans | on
> > synchronous_commit | on
> > synchronous_standby_names |
> > tcp_keepalives_count | 0
> > tcp_keepalives_idle | -1
> > tcp_keepalives_interval | 0
> > track_activities | on
> > track_activity_query_size | 1024
> > track_counts | on
> > track_functions | none
> > transaction_deferrable | off
> > transaction_isolation | read committed
> > transaction_read_only | off
> > transform_null_equals | off
> > update_process_title | on
> > vacuum_cost_delay | 0
> > vacuum_cost_limit | 200
> > vacuum_cost_page_dirty | 20
> > vacuum_cost_page_hit | 1
> > vacuum_cost_page_miss | 10
> > vacuum_defer_cleanup_age | 0
> > vacuum_freeze_min_age | 50000000
> > vacuum_freeze_table_age | 150000000
> > 
>  
>