search

syndesisio / syndesis

This project is archived. A flexible, customizable, open source platform that provides core integration capabilities as a service.
https://syndesis.io/
Apache License 2.0
597 stars 203 forks source link

[1.7.8] No activities after small load (~80000 messages in 20hours) #6052

Closed mmelko closed 5 years ago

mmelko commented 5 years ago

See also https://issues.jboss.org/browse/ENTESB-11407

This is a...


[ ] Feature request
[ ] Regression (a behavior that used to work and stopped working in a new release)
[x] Bug report  
[ ] Documentation issue or request

Description

After putting some small load (~3 messages /s ) for couple of hours no activities are listed in integrations. I hit this also on i-dev cluster and openshift pro. screenshot_20190703_111436 GET https://syndesis-test.b6ff.rh-idev.openshiftapps.com/api/v1/activity/integrations/i-LilthRWl7ZNNJJhTBQNz results in 504 Gateway timeout. Looks like connection to DB is really slow.

There is syndesis-test project on i-dev cluster that can be used for investigation.

heiko-braun commented 5 years ago

@zregvart Do you want to take stab at this?

zregvart commented 5 years ago

First thing to notice is that PostgreSQL is using all available memory: Screenshot_2019-07-03 OpenShift Web Console

zregvart commented 5 years ago

There are some activities in the database:

syndesis=# select count(*) from jsondb where path like '/act%';
 count 
-------
  1592
(1 row)
zregvart commented 5 years ago

I've increased the memory limit to double the available memory to 512MB. After redeploy Postgresql is using 17MB and the activities can be seen in the UI.

zregvart commented 5 years ago

After few minutes the memory usage is 467MB.

claudio4j commented 5 years ago

@mmelko how do I access -dev cluster ? Or can you provide the integration project for me to run locally would be good too.

zregvart commented 5 years ago

@claudio4j you can access the test project that @mmelko has setup here:

https://syndesis-test.b6ff.rh-idev.openshiftapps.com/

zregvart commented 5 years ago

Today activities load, they even load surprisingly fast (110-120msec). There are two possibilities that I'm considering:

  1. increase in memory from 255MB to 512MB for the syndesis-db/postgresql helped
  2. at the point we noticed this the database was not responding promptly due to the nature it was in (for example a deadlock occurred)

We can increase the memory in the template. I'm worried about the quota limits we have on the evaluation cluster, and if I'm not mistaking the quota is 4GiB. Right now with todo and komodo enabled the maximum memory is 4382MiB. Without todo and komodo we're at 3102MiB. Each integration pod launched has a maximum of 512MiB by default.

christophd commented 5 years ago

I spoke to @zregvart and maybe it is a good idea to repeat the test setup with 256MB for the syndesis-db once more forcing the error to occur another time.

Once the error is there we should have a look at the logs and postgres state first. Then just restart the DB (without increasing the memory) to see if this restart only solved the problem (when #6054 is happening because of the restart we are doomed).

Then increase the memory to 512MB and restart the DB to see if this really solves the issue for now.

heiko-braun commented 5 years ago

Related to https://github.com/syndesisio/syndesis/issues/5989 ?

zregvart commented 5 years ago

We have this reproduced currently on rh-idev in the mmelko-test project.

Here's what can be observed:

From postgres container in syndesis-db pod:

$ ps auxww
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
1016510+     1  0.0  0.0 169760 11900 ?        Ss   Jul08   0:14 postgres
1016510+   105  0.0  0.4 169876 69908 ?        Ss   Jul08   0:01 postgres: checkpointer process  
1016510+   106  0.0  0.4 169760 69676 ?        Ss   Jul08   0:18 postgres: writer process  
1016510+   107  0.0  0.0 169760  3688 ?        Ss   Jul08   0:04 postgres: wal writer process  
1016510+   108  0.0  0.1 170132 22808 ?        Ss   Jul08   0:04 postgres: autovacuum launcher process  
1016510+   109  0.0  0.0  95452  1924 ?        Ss   Jul08   0:33 postgres: stats collector process  
1016510+   116  0.0  0.0 171788  7724 ?        Ss   Jul08   0:00 postgres: syndesis syndesis ::1(50730) idle
1016510+  6004  0.3  0.3 236264 49248 ?        Ss   06:46   0:00 postgres: autovacuum worker process   syndesis
1016510+  6159  0.0  0.0  11820  1852 ?        Ss   06:48   0:00 /bin/sh
1016510+  6170  0.0  0.0  51744  1736 ?        R+   06:48   0:00 ps auxww
1016510+  8455  0.0  0.4 171052 68344 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(38684) idle
1016510+  8456  0.0  0.4 172128 74500 ?        Ds   Jul08   0:47 postgres: syndesis syndesis 10.1.0.1(38690) BIND
1016510+  8457  0.0  0.4 172076 74544 ?        Ss   Jul08   0:49 postgres: syndesis syndesis 10.1.0.1(38692) BIND
1016510+  8458  0.4  0.4 172208 74976 ?        Ds   Jul08   4:40 postgres: syndesis syndesis 10.1.0.1(38694) SELECT
1016510+  8459  0.0  0.3 171764 50256 ?        Ss   Jul08   0:03 postgres: syndesis syndesis 10.1.0.1(38698) idle in transaction
1016510+  8460  0.0  0.4 172196 74828 ?        Ss   Jul08   0:45 postgres: syndesis syndesis 10.1.0.1(38702) idle
1016510+  8461  0.4  0.4 172764 75020 ?        Ds   Jul08   4:59 postgres: syndesis syndesis 10.1.0.1(38704) INSERT
1016510+  8462  0.0  0.4 172380 74860 ?        Ss   Jul08   0:05 postgres: syndesis syndesis 10.1.0.1(38706) idle
1016510+  8463  0.2  0.4 172604 75204 ?        Ss   Jul08   2:37 postgres: syndesis syndesis 10.1.0.1(38708) idle
1016510+  8464  0.0  0.1 171780 23460 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(38710) idle in transaction
1016510+ 13270  0.0  0.4 170832 70096 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(53158) idle
1016510+ 13439  0.0  0.4 171052 67184 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(54908) idle
1016510+ 13702  0.0  0.0 170716  6884 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(57430) idle

The two connections in BIND and the two connections taking great deal of time (4:40h and 4:59h) are in INSERT and SELECT.

This shows waiting=f (not locked) for all of those connections:

datid datname pid usesysid usename application_name client_addr client_hostname client_port backend_start xact_start query_start state_change waiting state backend_xid backend_xmin query
16385 syndesis 116 16384 syndesis   ::1   50730 2019-07-08 10:07:38.97224+00   2019-07-08 10:07:38.997467+00 2019-07-08 10:07:38.997698+00 f idle     SELECT * FROM pg_stat_database_conflicts;
16385 syndesis 8455 16384 syndesis   10.1.0.1   38684 2019-07-08 11:47:39.095637+00   2019-07-08 19:20:47.685455+00 2019-07-08 19:20:47.685462+00 f idle     COMMIT
16385 syndesis 8456 16384 syndesis   10.1.0.1   38690 2019-07-08 11:47:39.2171+00 2019-07-09 07:01:51.261447+00 2019-07-09 07:01:51.261634+00 2019-07-09 07:01:51.261634+00 f active   19337 select path,value,ovalue from jsondb where path LIKE $1 order by path ASC
16385 syndesis 8457 16384 syndesis   10.1.0.1   38692 2019-07-08 11:47:39.223197+00   2019-07-09 07:01:52.167062+00 2019-07-09 07:01:52.16707+00 f idle     COMMIT
16385 syndesis 8458 16384 syndesis   10.1.0.1   38694 2019-07-08 11:47:39.289295+00 2019-07-09 07:01:13.705127+00 2019-07-09 07:01:13.705164+00 2019-07-09 07:01:13.705166+00 f active   19337 DELETE FROM jsondb WHERE path LIKE $1 AND path NOT IN (SELECT path FROM jsondb WHERE path LIKE $2 ORDER BY path DESC FETCH FIRST ($3) ROWS ONLY)
16385 syndesis 8459 16384 syndesis   10.1.0.1   38698 2019-07-08 11:47:39.295275+00 2019-07-08 12:12:34.9347+00 2019-07-08 12:12:34.935954+00 2019-07-08 12:12:34.93751+00 f idle in transaction   2053 SELECT p.proname,p.oid FROM pg_catalog.pg_proc p, pg_catalog.pg_namespace n WHERE p.pronamespace=n.oid AND n.nspname='pg_catalog' AND ( proname = 'lo_open' or proname = 'lo_close' or proname = 'lo_creat' or proname = 'lo_unlink' or proname = 'lo_lseek' or proname = 'lo_lseek64' or proname = 'lo_tell' or proname = 'lo_tell64' or proname = 'loread' or proname = 'lowrite' or proname = 'lo_truncate' or proname = 'lo_truncate64')
16385 syndesis 8460 16384 syndesis   10.1.0.1   38702 2019-07-08 11:47:39.302807+00   2019-07-09 06:56:46.971158+00 2019-07-09 06:56:46.971166+00 f idle     COMMIT
16385 syndesis 8461 16384 syndesis   10.1.0.1   38704 2019-07-08 11:47:39.308545+00 2019-07-09 07:00:55.693691+00 2019-07-09 07:01:04.960529+00 2019-07-09 07:01:04.960529+00 f active 19337 19337 INSERT into jsondb (path, value, ovalue) values ($1, $2, $3) ON CONFLICT (path) DO UPDATE SET value = $4, ovalue = $5
16385 syndesis 8462 16384 syndesis   10.1.0.1   38706 2019-07-08 11:47:39.314264+00   2019-07-09 06:55:46.839088+00 2019-07-09 06:55:46.839096+00 f idle     COMMIT
16385 syndesis 8463 16384 syndesis   10.1.0.1   38708 2019-07-08 11:47:39.319878+00   2019-07-09 06:52:51.675959+00 2019-07-09 06:52:51.675964+00 f idle     COMMIT
16385 syndesis 8464 16384 syndesis   10.1.0.1   38710 2019-07-08 11:47:39.325438+00 2019-07-08 11:50:19.685162+00 2019-07-08 11:50:19.690007+00 2019-07-08 11:50:19.697077+00 f idle in transaction   1021 SELECT p.proname,p.oid FROM pg_catalog.pg_proc p, pg_catalog.pg_namespace n WHERE p.pronamespace=n.oid AND n.nspname='pg_catalog' AND ( proname = 'lo_open' or proname = 'lo_close' or proname = 'lo_creat' or proname = 'lo_unlink' or proname = 'lo_lseek' or proname = 'lo_lseek64' or proname = 'lo_tell' or proname = 'lo_tell64' or proname = 'loread' or proname = 'lowrite' or proname = 'lo_truncate' or proname = 'lo_truncate64')
16385 syndesis 7166 10 postgres                       19336 <insufficient privilege>
16385 syndesis 13270 16384 syndesis   10.1.0.1   53158 2019-07-08 19:14:52.321318+00   2019-07-09 06:49:56.394386+00 2019-07-09 06:49:56.394393+00 f idle     COMMIT
16385 syndesis 13439 16384 syndesis   10.1.0.1   54908 2019-07-08 19:16:52.630924+00   2019-07-08 19:19:46.597692+00 2019-07-08 19:19:58.986476+00 f idle     select path,value,ovalue from jsondb where path LIKE $1 order by path ASC
16385 syndesis 13702 16384 syndesis   10.1.0.1   57430 2019-07-08 19:19:55.143315+00   2019-07-08 19:19:57.667168+00 2019-07-08 19:19:57.667225+00 f idle     COMMIT
16385 syndesis 6482 16384 syndesis psql     -1 2019-07-09 06:52:19.423434+00 2019-07-09 07:01:52.28866+00 2019-07-09 07:01:52.28866+00 2019-07-09 07:01:52.288663+00 f active   19337 select * from pg_stat_activity;

(16 rows)

Thread dumps from the server pod:

$ jstack 1
2019-07-09 07:06:31
Full thread dump OpenJDK 64-Bit Server VM (25.151-b12 mixed mode):

"Attach Listener" #201 daemon prio=9 os_prio=0 tid=0x00007fc84c01ba10 nid=0x175 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Logs Controller [running], streaming: https://kubernetes.default.svc/api/v1/namespaces/mmelko-test/pods/i-first-guess-3-p4d5s/log?pretty=false&follow=true&timestamps=true&sinceTime=2019-07-09T06:17:23.692151766Z" #199 prio=5 os_prio=0 tid=0x0000000001e73bf0 nid=0x15d waiting on condition [0x00007fc850084000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e925edc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingDeque.putLast(LinkedBlockingDeque.java:396)
    at java.util.concurrent.LinkedBlockingDeque.put(LinkedBlockingDeque.java:649)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLine(PodLogMonitor.java:261)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLogStream(PodLogMonitor.java:152)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:128)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:51)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1.lambda$onResponse$0(KubernetesSupport.java:110)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1$$Lambda$347/1836573690.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Logs Controller [running], streaming: https://kubernetes.default.svc/api/v1/namespaces/mmelko-test/pods/i-provide-feedback-6-m9gnf/log?pretty=false&follow=true&timestamps=true&sinceTime=2019-07-09T04:25:26.077473027Z" #197 prio=5 os_prio=0 tid=0x0000000001eb4fd0 nid=0x15b waiting on condition [0x00007fc8500f6000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e925edc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingDeque.putLast(LinkedBlockingDeque.java:396)
    at java.util.concurrent.LinkedBlockingDeque.put(LinkedBlockingDeque.java:649)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLine(PodLogMonitor.java:261)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLogStream(PodLogMonitor.java:152)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:128)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:51)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1.lambda$onResponse$0(KubernetesSupport.java:110)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1$$Lambda$347/1836573690.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Logs Controller [running], streaming: https://kubernetes.default.svc/api/v1/namespaces/mmelko-test/pods/i-create-new-number-4-2ctzv/log?pretty=false&follow=true&timestamps=true&sinceTime=2019-07-09T06:07:26.155247563Z" #195 prio=5 os_prio=0 tid=0x0000000001eb37d0 nid=0x159 waiting on condition [0x00007fc8600b4000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e925edc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingDeque.putLast(LinkedBlockingDeque.java:396)
    at java.util.concurrent.LinkedBlockingDeque.put(LinkedBlockingDeque.java:649)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLine(PodLogMonitor.java:261)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLogStream(PodLogMonitor.java:152)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:128)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:51)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1.lambda$onResponse$0(KubernetesSupport.java:110)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1$$Lambda$347/1836573690.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Logs Controller [running], streaming: https://kubernetes.default.svc/api/v1/namespaces/mmelko-test/pods/i-stats-guess-1-785sx/log?pretty=false&follow=true&timestamps=true&sinceTime=2019-07-09T04:18:35.530242062Z" #192 prio=5 os_prio=0 tid=0x0000000001e6f1c0 nid=0x156 waiting on condition [0x00007fc8500bd000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e925edc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingDeque.putLast(LinkedBlockingDeque.java:396)
    at java.util.concurrent.LinkedBlockingDeque.put(LinkedBlockingDeque.java:649)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLine(PodLogMonitor.java:261)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.processLogStream(PodLogMonitor.java:152)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:128)
    at io.syndesis.server.logging.jsondb.controller.PodLogMonitor.accept(PodLogMonitor.java:51)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1.lambda$onResponse$0(KubernetesSupport.java:110)
    at io.syndesis.server.logging.jsondb.controller.KubernetesSupport$1$$Lambda$347/1836573690.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Okio Watchdog" #185 daemon prio=5 os_prio=0 tid=0x00007fc7ec0612c0 nid=0x14f in Object.wait() [0x00007fc805238000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at okio.AsyncTimeout.awaitTimeout(AsyncTimeout.java:347)
    at okio.AsyncTimeout$Watchdog.run(AsyncTimeout.java:312)
    - locked <0x00000000e8c86980> (a java.lang.Class for okio.AsyncTimeout)

"XNIO-2 task-10" #83 prio=5 os_prio=0 tid=0x00007fc7f402aad0 nid=0xe9 waiting on condition [0x00007fc7e3ffe000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-9" #82 prio=5 os_prio=0 tid=0x00007fc7f402a1a0 nid=0xe8 waiting on condition [0x00007fc804331000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-8" #81 prio=5 os_prio=0 tid=0x00007fc7f4018bb0 nid=0xe7 waiting on condition [0x00007fc7e3efd000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-7" #80 prio=5 os_prio=0 tid=0x00007fc7f4018300 nid=0xe6 waiting on condition [0x00007fc7e3dfc000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-6" #79 prio=5 os_prio=0 tid=0x00007fc7f4194900 nid=0xe5 waiting on condition [0x00007fc7e24e9000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-5" #78 prio=5 os_prio=0 tid=0x00007fc7f41a86d0 nid=0xe4 waiting on condition [0x00007fc7e25ea000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-4" #77 prio=5 os_prio=0 tid=0x00007fc7f41a75c0 nid=0xe3 waiting on condition [0x00007fc7e26eb000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-3" #76 prio=5 os_prio=0 tid=0x00007fc7f4196950 nid=0xe2 waiting on condition [0x00007fc7e27ec000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-10" #75 prio=5 os_prio=0 tid=0x00007fc83005abc0 nid=0xe1 waiting on condition [0x00007fc7e28ed000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-2" #74 prio=5 os_prio=0 tid=0x00007fc7f4195a30 nid=0xe0 waiting on condition [0x00007fc7e29ee000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-9" #73 prio=5 os_prio=0 tid=0x00007fc830059460 nid=0xdf waiting on condition [0x00007fc7e2cef000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-8" #72 prio=5 os_prio=0 tid=0x00007fc830032470 nid=0xde waiting on condition [0x00007fc7e2df0000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-7" #71 prio=5 os_prio=0 tid=0x00007fc830031930 nid=0xdd waiting on condition [0x00007fc7e2ef1000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-6" #70 prio=5 os_prio=0 tid=0x00007fc830012420 nid=0xdc waiting on condition [0x00007fc7e31f2000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-5" #69 prio=5 os_prio=0 tid=0x00007fc8300108f0 nid=0xdb waiting on condition [0x00007fc7e32f3000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-4" #68 prio=5 os_prio=0 tid=0x00007fc83000f460 nid=0xda waiting on condition [0x00007fc7e33f4000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-3" #67 prio=5 os_prio=0 tid=0x00007fc83000e230 nid=0xd9 waiting on condition [0x00007fc7e34f5000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-2" #66 prio=5 os_prio=0 tid=0x00007fc830014400 nid=0xd8 waiting on condition [0x00007fc7e35f6000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-3 task-1" #65 prio=5 os_prio=0 tid=0x00007fc83000d690 nid=0xd7 waiting on condition [0x00007fc7e36f7000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ea07bc10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 task-1" #64 prio=5 os_prio=0 tid=0x00007fc7f412aee0 nid=0xd6 waiting on condition [0x00007fc7e37f8000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9c9bbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"DestroyJavaVM" #63 prio=5 os_prio=0 tid=0x00007fc878009ef0 nid=0x98 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"XNIO-3 Accept" #61 prio=5 os_prio=0 tid=0x00007fc879173ae0 nid=0xd5 runnable [0x00007fc7e38f9000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000ea09df28> (a sun.nio.ch.Util$3)
    - locked <0x00000000ea09df18> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000ea07cfb0> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"XNIO-3 I/O-2" #60 prio=5 os_prio=0 tid=0x00007fc8785b7050 nid=0xd4 runnable [0x00007fc7e39fa000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000ea07c300> (a sun.nio.ch.Util$3)
    - locked <0x00000000ea07c2f0> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000ea07c1d8> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"XNIO-3 I/O-1" #59 prio=5 os_prio=0 tid=0x00007fc878ffcc20 nid=0xd3 runnable [0x00007fc7e3afb000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000ea07c9e8> (a sun.nio.ch.Util$3)
    - locked <0x00000000ea07c9d8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000ea07c8c0> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"OkHttp ConnectionPool" #53 daemon prio=5 os_prio=0 tid=0x00007fc814002380 nid=0xcd in Object.wait() [0x00007fc80412f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:460)
    at okhttp3.ConnectionPool$1.run(ConnectionPool.java:67)
    - locked <0x00000000e925ec78> (a okhttp3.ConnectionPool)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-2 Accept" #46 prio=5 os_prio=0 tid=0x00007fc879065c50 nid=0xc6 runnable [0x00007fc804432000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e9cbea80> (a sun.nio.ch.Util$3)
    - locked <0x00000000e9cbea70> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e9c9cf70> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"XNIO-2 I/O-2" #45 prio=5 os_prio=0 tid=0x00007fc878f0f3d0 nid=0xc5 runnable [0x00007fc804533000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e9c9c2b0> (a sun.nio.ch.Util$3)
    - locked <0x00000000e9c9c2a0> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e9c9c188> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"XNIO-2 I/O-1" #44 prio=5 os_prio=0 tid=0x00007fc8785899a0 nid=0xc4 runnable [0x00007fc804634000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e9c9c9a0> (a sun.nio.ch.Util$3)
    - locked <0x00000000e9c9c990> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e9c9c878> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"spring.cloud.inetutils" #43 daemon prio=5 os_prio=0 tid=0x00007fc878e74a40 nid=0xc3 waiting on condition [0x00007fc804935000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e95b4bd8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Thread-17" #42 prio=5 os_prio=0 tid=0x00007fc878fe4290 nid=0xc2 waiting on condition [0x00007fc804c36000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e9674da8> (a java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
    at java.util.concurrent.FutureTask.get(FutureTask.java:191)
    at io.syndesis.server.update.controller.ResourceUpdateController.lambda$schedulerConfiguredFrom$3(ResourceUpdateController.java:154)
    at io.syndesis.server.update.controller.ResourceUpdateController$$Lambda$250/448569108.get(Unknown Source)
    at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
    at java.lang.Thread.run(Thread.java:748)

"ResourceUpdateController (scheduler)" #41 prio=5 os_prio=0 tid=0x00007fc878f35810 nid=0xc1 waiting on condition [0x00007fc804d37000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e96630c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-8-thread-1" #40 prio=5 os_prio=0 tid=0x00007fc878ed1ef0 nid=0xc0 waiting on condition [0x00007fc8501f7000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e92d26c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Logs Controller Scheduler [running]: cleanupLogs" #39 prio=5 os_prio=0 tid=0x00007fc8790b8e40 nid=0xbf runnable [0x00007fc86806a000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
    at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
    at org.postgresql.core.PGStream.receiveChar(PGStream.java:280)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1916)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:288)
    - locked <0x00000000e82d9d90> (a org.postgresql.core.v3.QueryExecutorImpl)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:430)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:356)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:168)
    at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:157)
    at sun.reflect.GeneratedMethodAccessor123.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
    at com.sun.proxy.$Proxy165.execute(Unknown Source)
    at org.skife.jdbi.v2.SQLStatement.internalExecute(SQLStatement.java:1327)
    at org.skife.jdbi.v2.Update.execute(Update.java:56)
    at org.skife.jdbi.v2.BasicHandle.update(BasicHandle.java:305)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.lambda$deleteKeepingRetention$1(ActivityTrackingController.java:169)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController$$Lambda$539/1312585640.inTransaction(Unknown Source)
    at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.inTransaction(LocalTransactionHandler.java:183)
    at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:338)
    at org.skife.jdbi.v2.DBI$5.withHandle(DBI.java:350)
    at org.skife.jdbi.v2.DBI.withHandle(DBI.java:298)
    at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:346)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.deleteKeepingRetention(ActivityTrackingController.java:163)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.cleanupLogs(ActivityTrackingController.java:145)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController$$Lambda$227/704387627.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Logs Controller [running]: processEventQueue" #38 prio=5 os_prio=0 tid=0x00007fc878ed10f0 nid=0xbe runnable [0x00007fc8680a3000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:171)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:140)
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:109)
    at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:67)
    at org.postgresql.core.PGStream.receiveChar(PGStream.java:280)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1916)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:460)
    - locked <0x00000000e82baff8> (a org.postgresql.core.v3.QueryExecutorImpl)
    at org.postgresql.jdbc.PgStatement.executeBatch(PgStatement.java:793)
    at org.postgresql.jdbc.PgPreparedStatement.executeBatch(PgPreparedStatement.java:1659)
    at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
    at com.sun.proxy.$Proxy165.executeBatch(Unknown Source)
    at org.skife.jdbi.v2.PreparedBatch.internalBatchExecute(PreparedBatch.java:196)
    at org.skife.jdbi.v2.PreparedBatch.execute(PreparedBatch.java:100)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.lambda$writeBatch$2(ActivityTrackingController.java:207)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController$$Lambda$532/1242313342.inTransaction(Unknown Source)
    at org.skife.jdbi.v2.tweak.transactions.LocalTransactionHandler.inTransaction(LocalTransactionHandler.java:183)
    at org.skife.jdbi.v2.BasicHandle.inTransaction(BasicHandle.java:338)
    at org.skife.jdbi.v2.DBI$5.withHandle(DBI.java:350)
    at org.skife.jdbi.v2.DBI.withHandle(DBI.java:298)
    at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:346)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.writeBatch(ActivityTrackingController.java:174)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController.processEventQueue(ActivityTrackingController.java:403)
    at io.syndesis.server.logging.jsondb.controller.ActivityTrackingController$$Lambda$224/666312528.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"OkHttp ConnectionPool" #36 daemon prio=5 os_prio=0 tid=0x00007fc7ec081e40 nid=0xbc in Object.wait() [0x00007fc805339000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:460)
    at okhttp3.ConnectionPool$1.run(ConnectionPool.java:67)
    - locked <0x00000000e86b48a8> (a okhttp3.ConnectionPool)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Endpoint Controller" #35 prio=5 os_prio=0 tid=0x00007fc879186bd0 nid=0xbb waiting on condition [0x00007fc80583a000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e89a2648> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Integration Controller Scheduler" #34 prio=5 os_prio=0 tid=0x00007fc7f4002e00 nid=0xba waiting on condition [0x00007fc80593b000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e89a1f50> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Integration Controller" #33 prio=5 os_prio=0 tid=0x00007fc7f40017e0 nid=0xb9 waiting on condition [0x00007fc805a3c000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e89a1638> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Integration Controller Scheduler" #32 prio=5 os_prio=0 tid=0x00007fc878c44470 nid=0xb8 waiting on condition [0x00007fc805b3d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e89a1f50> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"Tomcat JDBC Pool Cleaner[1282788025:1562586458994]" #30 daemon prio=5 os_prio=0 tid=0x00007fc878cd1320 nid=0xb6 in Object.wait() [0x00007fc8502f8000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000e8367fe0> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"Timer-0" #28 daemon prio=5 os_prio=0 tid=0x00007fc879224600 nid=0xb5 in Object.wait() [0x00007fc8505f9000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000e801d5b0> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"jaeger.RemoteReporter-FlushTimer" #27 daemon prio=5 os_prio=0 tid=0x00007fc879241270 nid=0xb4 in Object.wait() [0x00007fc8508fa000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000e801e690> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"jaeger.RemoteReporter-QueueProcessor" #26 daemon prio=5 os_prio=0 tid=0x00007fc879169320 nid=0xb3 waiting on condition [0x00007fc8509fb000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e801eb18> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
    at io.jaegertracing.internal.reporters.RemoteReporter$QueueProcessor.run(RemoteReporter.java:170)
    at java.lang.Thread.run(Thread.java:748)

"XNIO-1 Accept" #25 daemon prio=5 os_prio=0 tid=0x00007fc87844abf0 nid=0xb2 runnable [0x00007fc850afc000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e7f7c260> (a sun.nio.ch.Util$3)
    - locked <0x00000000e7f7c250> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e7f7c128> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"XNIO-1 I/O-1" #24 daemon prio=5 os_prio=0 tid=0x00007fc87898ee50 nid=0xb1 runnable [0x00007fc850bfd000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e7f7cd50> (a sun.nio.ch.Util$3)
    - locked <0x00000000e7f7cd40> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e7f7cc28> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
    at org.xnio.nio.WorkerThread.run(WorkerThread.java:511)

"SimplePauseDetectorThread_0" #23 daemon prio=9 os_prio=0 tid=0x00007fc82c04f2e0 nid=0xb0 waiting on condition [0x00007fc8601b5000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at org.LatencyUtils.TimeServices.sleepNanos(TimeServices.java:62)
    at org.LatencyUtils.SimplePauseDetector$SimplePauseDetectorThread.run(SimplePauseDetector.java:116)

"Thread-10" #22 daemon prio=9 os_prio=0 tid=0x00007fc82c049410 nid=0xaf waiting on condition [0x00007fc861cb6000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e7ed8288> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at org.LatencyUtils.PauseDetector$PauseDetectorThread.run(PauseDetector.java:85)

"Service Thread" #17 daemon prio=9 os_prio=0 tid=0x00007fc87826a530 nid=0xa9 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #16 daemon prio=9 os_prio=0 tid=0x00007fc878237de0 nid=0xa8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #15 daemon prio=9 os_prio=0 tid=0x00007fc87801bac0 nid=0xa7 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-6" #14 daemon prio=5 os_prio=0 tid=0x00007fc830000a30 nid=0xa6 runnable [0x00007fc8622ba000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e708c870> (a sun.nio.ch.Util$3)
    - locked <0x00000000e708c860> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e708c480> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:352)
    at java.lang.Thread.run(Thread.java:748)

"server-timer" #12 daemon prio=5 os_prio=0 tid=0x00007fc8782161b0 nid=0xa4 in Object.wait() [0x00007fc8625bd000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000e708cd48> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"Thread-4" #11 daemon prio=5 os_prio=0 tid=0x00007fc84808c1a0 nid=0xa3 runnable [0x00007fc862ad3000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000e709ec60> (a sun.nio.ch.Util$3)
    - locked <0x00000000e709ec50> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000e709eaa8> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:352)
    at java.lang.Thread.run(Thread.java:748)

"Jolokia Agent Cleanup Thread" #10 daemon prio=5 os_prio=0 tid=0x00007fc84808ad40 nid=0xa2 in Object.wait() [0x00007fc8624bc000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Thread.join(Thread.java:1252)
    - locked <0x00000000e89a1c58> (a java.lang.Thread)
    at java.lang.Thread.join(Thread.java:1326)
    at org.jolokia.jvmagent.CleanupThread.joinThreads(CleanupThread.java:110)
    at org.jolokia.jvmagent.CleanupThread.run(CleanupThread.java:60)

"Thread-2" #8 daemon prio=5 os_prio=0 tid=0x00007fc848087230 nid=0xa0 runnable [0x00007fc8626be000]
   java.lang.Thread.State: RUNNABLE
    at java.net.PlainDatagramSocketImpl.receive0(Native Method)
    - locked <0x00000000e709e8c0> (a java.net.PlainDatagramSocketImpl)
    at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
    - locked <0x00000000e709e8c0> (a java.net.PlainDatagramSocketImpl)
    at java.net.DatagramSocket.receive(DatagramSocket.java:812)
    - locked <0x00000000e71cfd30> (a java.net.DatagramPacket)
    - locked <0x00000000e709e870> (a java.net.MulticastSocket)
    at org.jolokia.discovery.MulticastSocketListenerThread.receiveMessage(MulticastSocketListenerThread.java:114)
    at org.jolokia.discovery.MulticastSocketListenerThread.run(MulticastSocketListenerThread.java:71)

"server-timer" #7 daemon prio=5 os_prio=0 tid=0x00007fc848070a20 nid=0x9f in Object.wait() [0x00007fc8627bf000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000e709f240> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fc87811bac0 nid=0x9d runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fc8780f30e0 nid=0x9c in Object.wait() [0x00007fc8630f7000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000000e71cfd58> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fc8780eeef0 nid=0x9b in Object.wait() [0x00007fc8631f8000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x00000000e71cfdf0> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"VM Thread" os_prio=0 tid=0x00007fc8780e5990 nid=0x9a runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fc87801e960 nid=0x99 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fc87826c180 nid=0xaa waiting on condition 

JNI global references: 1187
zregvart commented 5 years ago

This bit of code is issuing the DELETE:

https://github.com/syndesisio/syndesis/blob/eda2cb2af8be3d17c2b939153b2c6522a7e0e3ca/app/server/logging/jsondb/src/main/java/io/syndesis/server/logging/jsondb/controller/ActivityTrackingController.java#L162-L171

And the INSERT is from here:

https://github.com/syndesisio/syndesis/blob/eda2cb2af8be3d17c2b939153b2c6522a7e0e3ca/app/server/logging/jsondb/src/main/java/io/syndesis/server/logging/jsondb/controller/ActivityTrackingController.java#L173-L209

zregvart commented 5 years ago 
$ ps auxww; echo "select a.pid, a.query, l.mode from pg_locks l join pg_stat_activity a on a.pid = l.pid where l.mode = 'ExclusiveLock' and a.usename = 'syndesis';" | psql -H -U postgres
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
1016510+     1  0.0  0.0 169760 11900 ?        Ss   Jul08   0:16 postgres
1016510+   105  0.0  0.4 169876 69908 ?        Ss   Jul08   0:02 postgres: checkpointer process  
1016510+   106  0.0  0.4 169760 69676 ?        Ss   Jul08   0:20 postgres: writer process  
1016510+   107  0.0  0.0 169760  3688 ?        Ss   Jul08   0:04 postgres: wal writer process  
1016510+   108  0.0  0.1 170132 22808 ?        Ss   Jul08   0:04 postgres: autovacuum launcher process  
1016510+   109  0.0  0.0  95452  1924 ?        Ss   Jul08   0:38 postgres: stats collector process  
1016510+   116  0.0  0.0 171788  7724 ?        Ss   Jul08   0:00 postgres: syndesis syndesis ::1(50730) idle
1016510+  6159  0.0  0.0  11820  1848 ?        Ss   06:48   0:00 /bin/sh
1016510+  6481  0.0  0.0  80488  3840 ?        S+   06:52   0:00 psql -U syndesis
1016510+  6482  0.0  0.0 171824  9220 ?        Ss   06:52   0:00 postgres: syndesis syndesis [local] idle
1016510+  8175  0.0  0.0  11820  1912 ?        Ss+  07:12   0:00 /bin/sh
1016510+  8455  0.0  0.4 171052 68344 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(38684) idle
1016510+  8456  0.0  0.4 172128 74500 ?        Ss   Jul08   1:00 postgres: syndesis syndesis 10.1.0.1(38690) idle
1016510+  8457  0.0  0.4 172076 74544 ?        Ds   Jul08   1:00 postgres: syndesis syndesis 10.1.0.1(38692) DELETE
1016510+  8458  0.3  0.4 172208 74976 ?        Ss   Jul08   4:56 postgres: syndesis syndesis 10.1.0.1(38694) idle
1016510+  8459  0.0  0.3 171764 50256 ?        Ss   Jul08   0:03 postgres: syndesis syndesis 10.1.0.1(38698) idle in transaction
1016510+  8460  0.0  0.4 172196 74828 ?        Ss   Jul08   1:02 postgres: syndesis syndesis 10.1.0.1(38702) idle
1016510+  8461  0.3  0.4 172764 75020 ?        Ds   Jul08   5:15 postgres: syndesis syndesis 10.1.0.1(38704) INSERT
1016510+  8462  0.0  0.4 171020 73984 ?        Ds   Jul08   0:07 postgres: syndesis syndesis 10.1.0.1(38706) SELECT
1016510+  8463  0.2  0.4 172604 75204 ?        Ss   Jul08   2:38 postgres: syndesis syndesis 10.1.0.1(38708) idle
1016510+  8464  0.0  0.1 171780 23460 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(38710) idle in transaction
1016510+ 13270  0.0  0.4 170832 70096 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(53158) idle
1016510+ 13439  0.0  0.4 171052 67184 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(54908) idle
1016510+ 13702  0.0  0.0 170716  6884 ?        Ss   Jul08   0:00 postgres: syndesis syndesis 10.1.0.1(57430) idle
1016510+ 19522  0.0  0.0  11820  1860 ?        Ss   09:28   0:00 /bin/sh
1016510+ 20717  0.5  0.0 236264 14384 ?        Ds   09:42   0:00 postgres: autovacuum worker process   syndesis
1016510+ 20743  0.0  0.0  51744  1732 ?        R+   09:42   0:00 ps auxww
pid query mode
8457 DELETE FROM jsondb WHERE path LIKE $1 AND path NOT IN (SELECT path FROM jsondb WHERE path LIKE $2 ORDER BY path DESC FETCH FIRST ($3) ROWS ONLY) ExclusiveLock
8459 SELECT p.proname,p.oid FROM pg_catalog.pg_proc p, pg_catalog.pg_namespace n WHERE p.pronamespace=n.oid AND n.nspname='pg_catalog' AND ( proname = 'lo_open' or proname = 'lo_close' or proname = 'lo_creat' or proname = 'lo_unlink' or proname = 'lo_lseek' or proname = 'lo_lseek64' or proname = 'lo_tell' or proname = 'lo_tell64' or proname = 'loread' or proname = 'lowrite' or proname = 'lo_truncate' or proname = 'lo_truncate64') ExclusiveLock
8461 INSERT into jsondb (path, value, ovalue) values ($1, $2, $3) ON CONFLICT (path) DO UPDATE SET value = $4, ovalue = $5 ExclusiveLock
8461 INSERT into jsondb (path, value, ovalue) values ($1, $2, $3) ON CONFLICT (path) DO UPDATE SET value = $4, ovalue = $5 ExclusiveLock
8462 select path,value,ovalue from jsondb where path LIKE $1 order by path DESC ExclusiveLock
8464 SELECT p.proname,p.oid FROM pg_catalog.pg_proc p, pg_catalog.pg_namespace n WHERE p.pronamespace=n.oid AND n.nspname='pg_catalog' AND ( proname = 'lo_open' or proname = 'lo_close' or proname = 'lo_creat' or proname = 'lo_unlink' or proname = 'lo_lseek' or proname = 'lo_lseek64' or proname = 'lo_tell' or proname = 'lo_tell64' or proname = 'loread' or proname = 'lowrite' or proname = 'lo_truncate' or proname = 'lo_truncate64') ExclusiveLock

(6 rows)

This shows that two pids (8457 and 8461) have ExclusiveLock, probably over the same row.

My current thinking is that we could add FOR UPDATE SKIP LOCKED to the inner SELECT of the DELETE statement.

@mmelko I can do an experiment in building a custom version of Syndesis 1.7.x with that FOR UPDATE SKIP LOCKED and deploy it to the rh-idev cluster in a new project. Can you run the tests against it to confirm if it solves the issue?

zregvart commented 5 years ago

Actually because of the NOT IN we don't want to skip over the locked rows, those might be locked by an INSERT and should not be deleted.

zregvart commented 5 years ago

This caught my eye, from the database log:

2019-07-09 13:30:08 UTC   00000 5d2495d5.1b21 LOG:  automatic vacuum of table "syndesis.public.jsondb": index scans: 0
    pages: 0 removed, 43298 remain, 980 skipped due to pins
    tuples: 0 removed, 575705 remain, 526219 are dead but not yet removable
    buffer usage: 51779 hits, 45521 misses, 5 dirtied
    avg read rate: 1.333 MB/s, avg write rate: 0.000 MB/s
system usage: CPU 0.36s/0.17u sec elapsed 266.74 sec

I've tried vacuuming the jsondb table manually:

syndesis=> vacuum verbose jsondb;
INFO:  vacuuming "public.jsondb"
INFO:  index "jsondb_pkey" now contains 545824 row versions in 11646 pages
DETAIL:  0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.06s/0.02u sec elapsed 22.24 sec.
INFO:  index "jsondb_idx" now contains 374 row versions in 7 pages
DETAIL:  0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.04 sec.
INFO:  "jsondb": found 0 removable, 574779 nonremovable row versions in 43271 out of 43406 pages
DETAIL:  541225 dead row versions cannot be removed yet.
There were 11502 unused item pointers.
Skipped 135 pages due to buffer pins.
0 pages are entirely empty.
CPU 0.32s/0.15u sec elapsed 63.15 sec.
INFO:  vacuuming "pg_toast.pg_toast_16436"
INFO:  index "pg_toast_16436_index" now contains 117 row versions in 2 pages
DETAIL:  0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "pg_toast_16436": found 0 removable, 0 nonremovable row versions in 0 out of 51 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
Skipped 0 pages due to buffer pins.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.02 sec.
VACUUM

I think that high number of non-removable rows (574779) is causing queries to run slow, so the inner SELECT for the DELETE is causing the ExclusiveLock which prevents the INSERT, or the other way around the ExclusiveLock created by the INSERT (that's slow) is preventing the DELETE from finishing.

zregvart commented 5 years ago

According to:

SELECT schemaname, relname, n_live_tup, n_dead_tup, last_autovacuum
FROM pg_stat_all_tables
WHERE relname = 'jsondb'
ORDER BY n_dead_tup
    / (n_live_tup
       * current_setting('autovacuum_vacuum_scale_factor')::float8
          + current_setting('autovacuum_vacuum_threshold')::float8)
schemaname relname n_live_tup n_dead_tup last_autovacuum
public jsondb 34647 543113 2019-07-09 13:44:53.064172+00

(1 row)

The autovacuum is getting triggered but there are still a great number of dead tuples.

zregvart commented 5 years ago

Seems that the ORDER by PATH DESC is where we loose the most performance.

Without it:

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%';
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using jsondb_pkey on jsondb  (cost=0.55..8.57 rows=5847 width=119) (actual time=97334.348..97920.892 rows=758 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 112569
 Planning time: 739.563 ms
 Execution time: 97920.976 ms
(6 rows)

With it: never finishes (I get kicked out of oc rsh, could be due to a timeout or OOM killer):

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%' ORDER BY path DESC;
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.55..8.57 rows=5843 width=119) (actual time=529.474..612900.143 rows=758 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 112569
 Planning time: 259.770 ms
 Execution time: 612900.246 ms
(6 rows)

I'm considering adding a sorted index based on a substring of the path column just for activity entry id, if such a thing is possible in PostgreSQL.

heiko-braun commented 5 years ago

What's the order by path ... fetch first N doing? Why is it there?

zregvart commented 5 years ago

I've created an index:

CREATE INDEX CONCURRENTLY jsondb_activity_idx ON jsondb (path DESC) WHERE path LIKE '/activity/exchanges/%';

I'm not 100% on the WHERE path LIKE ... bit, and how it'll influence the planner to choose to use this index or not.

I've scaled syndesis-server down in order to run VACUUM ANALYSE jsondb, now there are far less dead tuples:

schemaname relname n_live_tup n_dead_tup last_autovacuum
public jsondb 58961 170 2019-07-09 14:49:19.88409+00

(1 row)

With this I can see the activities in the UI, I think we need to let it cook a bit and check back in 12 or so hours to see if the number of dead tuples keeps increasing or the queries take long time.

zregvart commented 5 years ago

What's the order by path ... fetch first N doing? Why is it there?

That query deletes all but the last 50 activity entries for a integration.

The SELECT selects the last 50 entries, the DELETE deletes all but those. There are no joins supported in DELETE that's why we need NOT IN.

zregvart commented 5 years ago

I'm actually quite certain that the newly created index won't help. I'll try to redefine the index without the WHERE path LIKE... part.

Seems that the planner is using the jsondb_pkey index intermittently, and the jsondb_activity_idx only for exact WHERE path LIKE... condition.

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%' ORDER BY path DESC;
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.54..8.56 rows=3 width=121) (actual time=0.063..0.100 rows=50 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 0
 Planning time: 1.186 ms
 Execution time: 0.140 ms
(6 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/%' ORDER BY path DESC;
                                                               QUERY PLAN                                                                
-----------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.54..8.56 rows=308 width=121) (actual time=0.043..1.043 rows=1146 loops=1)
   Index Cond: ((path >= '/activity/exchanges/'::text) AND (path < '/activity/exchanges0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/%'::text)
   Heap Fetches: 863
 Planning time: 0.382 ms
 Execution time: 1.102 ms
(6 rows)

syndesis=> \d jsondb
              Table "public.jsondb"
 Column |       Type        |     Modifiers      
--------+-------------------+--------------------
 path   | character varying | collate C not null
 value  | character varying | 
 ovalue | character varying | 
 idx    | character varying | collate C
Indexes:
    "jsondb_pkey" PRIMARY KEY, btree (path)
    "jsondb_activity_idx" btree (path DESC) WHERE path::text ~~ '/activity/exchanges/%'::text
    "jsondb_idx" btree (idx, value) WHERE idx IS NOT NULL

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/%' ORDER BY path DESC;
                                                               QUERY PLAN                                                               
----------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using jsondb_activity_idx on jsondb  (cost=0.40..8.42 rows=950 width=119) (actual time=0.026..0.645 rows=1283 loops=1)
   Index Cond: ((path >= '/activity/exchanges/'::text) AND (path < '/activity/exchanges0'::text))
   Heap Fetches: 1000
 Planning time: 0.422 ms
 Execution time: 0.696 ms
(5 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/%' ORDER BY path DESC;
                                                               QUERY PLAN                                                               
----------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using jsondb_activity_idx on jsondb  (cost=0.40..8.42 rows=950 width=119) (actual time=0.013..0.482 rows=1314 loops=1)
   Index Cond: ((path >= '/activity/exchanges/'::text) AND (path < '/activity/exchanges0'::text))
   Heap Fetches: 1031
 Planning time: 0.361 ms
 Execution time: 0.542 ms
(5 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%' ORDER BY path DESC;
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.54..8.56 rows=3 width=119) (actual time=0.020..0.041 rows=50 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 0
 Planning time: 0.220 ms
 Execution time: 0.053 ms
(6 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%' ORDER BY path DESC;
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.54..8.56 rows=3 width=119) (actual time=0.022..0.034 rows=50 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 0
 Planning time: 0.238 ms
 Execution time: 0.050 ms
(6 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%' ORDER BY path DESC;
                                                                   QUERY PLAN                                                                   
------------------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan Backward using jsondb_pkey on jsondb  (cost=0.54..8.56 rows=3 width=119) (actual time=0.020..0.041 rows=50 loops=1)
   Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0'::text))
   Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz/%'::text)
   Heap Fetches: 0
 Planning time: 0.231 ms
 Execution time: 0.056 ms
(6 rows)

syndesis=> explain analyse select path from jsondb where path like '/activity/exchanges/%' ORDER BY path DESC;
                                                               QUERY PLAN                                                               
----------------------------------------------------------------------------------------------------------------------------------------
 Index Only Scan using jsondb_activity_idx on jsondb  (cost=0.40..8.42 rows=950 width=119) (actual time=0.019..0.799 rows=1378 loops=1)
   Index Cond: ((path >= '/activity/exchanges/'::text) AND (path < '/activity/exchanges0'::text))
   Heap Fetches: 1095
 Planning time: 0.515 ms
 Execution time: 0.882 ms
(5 rows)
zregvart commented 5 years ago

The new index is:

CREATE INDEX CONCURRENTLY jsondb_activity_idx ON jsondb (path DESC);

And it results in this execution plan:

syndesis=> explain analyse DELETE FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/%' AND path NOT IN (SELECT path FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/%' ORDER BY path DESC FETCH FIRST (50) ROWS ONLY);
                                                                               QUERY PLAN                                                                               
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on jsondb  (cost=8.85..16.88 rows=2 width=6) (actual time=0.013..0.013 rows=0 loops=1)
   ->  Index Scan using jsondb_activity_idx on jsondb  (cost=8.85..16.88 rows=2 width=6) (actual time=0.009..0.009 rows=0 loops=1)
         Index Cond: (((path)::text >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/'::text) AND ((path)::text < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz00'::text))
         Filter: (((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/%'::text) AND (NOT (hashed SubPlan 1)))
         SubPlan 1
           ->  Limit  (cost=0.41..8.43 rows=3 width=118) (never executed)
                 ->  Index Only Scan using jsondb_activity_idx on jsondb jsondb_1  (cost=0.41..8.43 rows=3 width=118) (never executed)
                       Index Cond: ((path >= '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/'::text) AND (path < '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz00'::text))
                       Filter: ((path)::text ~~ '/activity/exchanges/i-LjGC-0XNPX6fkTQoWYDz0/%'::text)
                       Heap Fetches: 0
 Planning time: 0.543 ms
 Execution time: 0.042 ms
(12 rows)

The index is now used. I think to be certain that there are no deadlocks we need to restructure the DELETE query, perhaps using WITH and either UNCOMMITED READ (not sure it's supported on PostgresSQL) or SKIP LOCKED.

zregvart commented 5 years ago

I've considered using OIDs as criteria instead of the path column:

syndesis=> ALTER TABLE jsondb SET WITH OIDS;
ALTER TABLE

This performs worse:

syndesis=> explain analyse DELETE FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' AND oid NOT IN (SELECT oid FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' ORDER BY path DESC FETCH FIRST (50) ROWS ONLY);
                                                                                     QUERY PLAN                                                                                     
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on jsondb  (cost=2.07..10.10 rows=179 width=6) (actual time=1.192..1.192 rows=0 loops=1)
   ->  Index Scan using jsondb_activity_idx on jsondb  (cost=2.07..10.10 rows=179 width=6) (actual time=0.157..0.835 rows=452 loops=1)
         Index Cond: (((path)::text >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND ((path)::text < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
         Filter: (((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text) AND (NOT (hashed SubPlan 1)))
         Rows Removed by Filter: 50
         SubPlan 1
           ->  Limit  (cost=0.41..1.53 rows=50 width=117) (actual time=0.012..0.074 rows=50 loops=1)
                 ->  Index Scan using jsondb_activity_idx on jsondb jsondb_1  (cost=0.41..8.44 rows=359 width=117) (actual time=0.012..0.067 rows=50 loops=1)
                       Index Cond: (((path)::text >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND ((path)::text < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
                       Filter: ((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text)
 Planning time: 0.868 ms
 Execution time: 1.234 ms
(12 rows)

syndesis=> explain analyse DELETE FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' AND path NOT IN (SELECT path FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' ORDER BY path DESC FETCH FIRST (50) ROWS ONLY);
                                                                              QUERY PLAN                                                                              
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on jsondb  (cost=2.07..10.10 rows=179 width=6) (actual time=0.764..0.764 rows=0 loops=1)
   ->  Index Scan using jsondb_activity_idx on jsondb  (cost=2.07..10.10 rows=179 width=6) (actual time=0.148..0.719 rows=63 loops=1)
         Index Cond: (((path)::text >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND ((path)::text < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
         Filter: (((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text) AND (NOT (hashed SubPlan 1)))
         Rows Removed by Filter: 50
         SubPlan 1
           ->  Limit  (cost=0.41..1.53 rows=50 width=113) (actual time=0.038..0.084 rows=50 loops=1)
                 ->  Index Only Scan using jsondb_activity_idx on jsondb jsondb_1  (cost=0.41..8.44 rows=359 width=113) (actual time=0.037..0.078 rows=50 loops=1)
                       Index Cond: ((path >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND (path < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
                       Filter: ((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text)
                       Heap Fetches: 50
 Planning time: 0.657 ms
 Execution time: 0.805 ms
(13 rows)

WITH variant:

syndesis=> explain analyse WITH d AS (SELECT oid FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' ORDER BY path DESC OFFSET 50 ROWS) DELETE FROM jsondb WHERE oid IN (SELECT oid FROM d);
                                                                                  QUERY PLAN                                                                                  
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on jsondb  (cost=162.38..2984.76 rows=20704 width=34) (actual time=43.823..43.823 rows=0 loops=1)
   CTE d
     ->  Limit  (cost=0.47..8.44 rows=6642 width=111) (actual time=0.068..7.874 rows=6941 loops=1)
           ->  Index Scan using jsondb_activity_idx on jsondb jsondb_1  (cost=0.41..8.44 rows=6692 width=111) (actual time=0.021..7.384 rows=6991 loops=1)
                 Index Cond: (((path)::text >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND ((path)::text < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
                 Filter: ((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text)
   ->  Hash Join  (cost=153.94..2976.32 rows=20704 width=34) (actual time=18.690..31.731 rows=6941 loops=1)
         Hash Cond: (jsondb.oid = d.oid)
         ->  Seq Scan on jsondb  (cost=0.00..2665.09 rows=41409 width=10) (actual time=0.038..11.274 rows=41378 loops=1)
         ->  Hash  (cost=151.44..151.44 rows=200 width=32) (actual time=14.740..14.740 rows=6941 loops=1)
               Buckets: 8192 (originally 1024)  Batches: 1 (originally 1)  Memory Usage: 553kB
               ->  HashAggregate  (cost=149.44..151.44 rows=200 width=32) (actual time=12.677..13.631 rows=6941 loops=1)
                     Group Key: d.oid
                     ->  CTE Scan on d  (cost=0.00..132.84 rows=6642 width=32) (actual time=0.076..10.760 rows=6941 loops=1)
 Planning time: 0.568 ms
 Execution time: 44.029 ms
(16 rows)

syndesis=> explain analyse WITH d AS (SELECT path FROM jsondb WHERE path LIKE '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%' ORDER BY path DESC OFFSET 50 ROWS) DELETE FROM jsondb WHERE path IN (SELECT path FROM d);
                                                                          QUERY PLAN                                                                          
--------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on jsondb  (cost=8.87..16.91 rows=1 width=62) (actual time=0.816..0.816 rows=0 loops=1)
   CTE d
     ->  Limit  (cost=8.44..8.44 rows=1 width=115) (actual time=0.094..0.205 rows=98 loops=1)
           ->  Index Only Scan using jsondb_activity_idx on jsondb jsondb_1  (cost=0.41..8.44 rows=3 width=115) (actual time=0.032..0.198 rows=148 loops=1)
                 Index Cond: ((path >= '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/'::text) AND (path < '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz0'::text))
                 Filter: ((path)::text ~~ '/activity/exchanges/i-LjGDJG5NPX6fkTQoWYHz/%'::text)
                 Heap Fetches: 99
   ->  Nested Loop  (cost=0.44..8.47 rows=1 width=62) (actual time=0.324..0.686 rows=98 loops=1)
         ->  HashAggregate  (cost=0.02..0.03 rows=1 width=88) (actual time=0.313..0.329 rows=98 loops=1)
               Group Key: (d.path)::text
               ->  CTE Scan on d  (cost=0.00..0.02 rows=1 width=88) (actual time=0.099..0.259 rows=98 loops=1)
         ->  Index Scan using jsondb_activity_idx on jsondb  (cost=0.41..8.43 rows=1 width=121) (actual time=0.003..0.003 rows=1 loops=98)
               Index Cond: ((path)::text = (d.path)::text)
 Planning time: 0.754 ms
 Execution time: 0.869 ms
(15 rows)
zregvart commented 5 years ago

I think I'm settling on two chages:

heiko-braun commented 5 years ago

Thanks for the thorough investigation @zregvart. Changing the sql statements and redoing the load tests seems to safe, right?

zregvart commented 5 years ago

We had a test running over night just with the index added and the jsondb table VACUUM ANALYSEd, the same instance that has had the big number of dead tuples in https://github.com/syndesisio/syndesis/issues/6052#issuecomment-509649507.

I'm inclined to just add the index as the only code change and leave the queries as is.

heiko-braun commented 5 years ago

@mmelko Did you get a chance to verify of the improvement help (at least to a degree that we can lower the priority of this ticket?)

zregvart commented 5 years ago

Last test @mmelko performed was on 1.7.10 (perhaps @mmelko you can fill in the details of the test here), today after one day of running the test fetch of activities is failing with 504 Gateway timeout.

I've performed this maintenance on the installation:

# check to see if there are dead tuples (not vacuumed)
$ oc exec -c postgresql $(oc get pod -l 'syndesis.io/component=syndesis-db' --no-headers=true -o=custom-columns=x:.metadata.name) -- bash -c "echo SELECT schemaname, relname, n_live_tup, n_dead_tup, last_autovacuum FROM pg_stat_all_tables WHERE relname = \'jsondb\'|psql -U syndesis"

 schemaname | relname | n_live_tup | n_dead_tup |        last_autovacuum        
------------+---------+------------+------------+-------------------------------
 public     | jsondb  |      26893 |     491210 | 2019-07-17 09:26:51.264029+00
(1 row)

# since there are 491210 dead tuples, performed the following

# scaled down the server
$ oc scale --replicas=0 dc syndesis-server

# terminated all running connections
$ oc exec -c postgresql $(oc get pod -l 'syndesis.io/component=syndesis-db' --no-headers=true -o=custom-columns=x:.metadata.name) -- bash -c "echo SELECT pg_terminate_backend\(a.pid\) FROM pg_locks l join pg_stat_activity a ON a.pid = l.pid WHERE l.mode = \'ExclusiveLock\' AND a.usename = \'syndesis\'|psql -U syndesis"
FATAL:  terminating connection due to administrator command
server closed the connection unexpectedly
    This probably means the server terminated abnormally
    before or while processing the request.
connection to server was lost
command terminated with exit code 2

# the above FATAL output is expected the statement also closes the connection psql is using

# executed `VACUUM FULL ANALYSE`
$ oc exec -c postgresql $(oc get pod -l 'syndesis.io/component=syndesis-db' --no-headers=true -o=custom-columns=x:.metadata.name) -- bash -c "echo VACUUM FULL ANALYSE jsondb|psql -U syndesis"
VACUUM

# scaled up server
$ oc scale --replicas=1 dc syndesis-server

With this the activities are being fetched again. We can wait another day and see if this preventative maintenance is needed again tomorrow or it somehow fixes the issue, as it has, perplexingly/seemingly , fixed on this issue on an instance running 1.7.8

If this indeed seems to help, perhaps we can lower the priority of this as there is a possible workaround: performing the above maintenance.

zregvart commented 5 years ago

@mmelko do you think we can lower the priority with the maintenance steps outlined in https://github.com/syndesisio/syndesis/issues/6052#issuecomment-512181486?

My argument is that if this can be accepted as a workaround and we document it as a known limitation then we can address this issue in the activity tracking redesign planned for the next release.

mmelko commented 5 years ago

@zregvart I'd rather keep this as p0. I'd still to document it as know limitation. But compared to other p1's this is still more serious and will have bigger impact on some potential enterprise deployments.

heiko-braun commented 5 years ago

@zregvart Can you work with @TovaCohen on the release notes?

zregvart commented 5 years ago

Tracked downstream: https://issues.jboss.org/browse/FUSEDOC-3376

heiko-braun commented 5 years ago

Migrated to https://issues.jboss.org/browse/ENTESB-11407