Unexpected GeoServer CPU usage with Oracle data source

[loureiro]

We are doing some scalability tests with Linux, GeoServer 2.14.1, Java 1.8.0 and Oracle THIN 12.2. The database instance is on a separated server machine. We are using JMeter with multiple users and a constant request throughput (with enough idle time between user requests). We noticed that GeoServer CPU usage appears to dramatically increase with database response time. That happens, for example, if we use some slow views or if we force a latency on the database server network interface. It seems like that extra CPU is spent by the Oracle JDBC driver calls (as evidenced by Yourkit) and at the kernel space (as indicated by top/strace).

Has anybody experienced something similar? What could explain that behavior?

Thanks,

Joao

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[geowolf]

Hi,

I haven't experienced that behavior. The driver is not part of the GeoServer source code, you should probably

ask on the Oracle support forums.

Given the behavior you're seeing, it reminds me of some sort of "busy wait" state, https://en.wikipedia.org/wiki/Busy_waiting

Cheers

Andrea

On Wed, Feb 6, 2019 at 7:56 PM João Loureiro Junior <[hidden email]> wrote:

We are doing some scalability tests with Linux, GeoServer 2.14.1, Java 1.8.0 and Oracle THIN 12.2. The database instance is on a separated server machine. We are using JMeter with multiple users and a constant request throughput (with enough idle time between user requests). We noticed that GeoServer CPU usage appears to dramatically increase with database response time. That happens, for example, if we use some slow views or if we force a latency on the database server network interface. It seems like that extra CPU is spent by the Oracle JDBC driver calls (as evidenced by Yourkit) and at the kernel space (as indicated by top/strace).

Has anybody experienced something similar? What could explain that behavior?

Thanks,

Joao

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

--


_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[loureiro]

Indeed, "busy-wait" was the first thing that came to my mind as well...

I did some more investigation on this issue. Below is the jvm-top output for the test while initially running without extra latency:

>>>

 JvmTop 0.8.0 alpha - 14:39:29,  amd64, 16 cpus, Linux 3.10.0-86, load avg 0.46

 http://code.google.com/p/jvmtop

 PID 10036: /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/jboss-modules.jar

 ARGS: -mp /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/modules org.jboss.a[...]

 VMARGS: -D[Server:spotdsno12] -D[pcid:316534345] -Xms2048m -Xmx8192m -XX:[...]

 VM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.8.0_144

 UP:  3:26m  #THR: 111  #THRPEAK: 187  #THRCREATED: 415  USER: apdsno12

 GC-Time:  0: 0m   #GC-Runs: 186       #TotalLoadedClasses: 33674

 CPU:  5.63% GC:  0.00% HEAP:1633m /8192m NONHEAP: 294m /1520m

  TID   NAME                                    STATE    CPU  TOTALCPU BLOCKEDBY

    403 default task-61                 TIMED_WAITING 10.02%     0.64%

    416 default task-64                 TIMED_WAITING  8.11%     0.07%

    422 default task-68                 TIMED_WAITING  7.60%     0.07%

    414 default task-63                 TIMED_WAITING  6.84%     0.07%

    424 default task-69                 TIMED_WAITING  6.02%     0.07%

    428 default task-70                 TIMED_WAITING  6.00%     0.07%

    423 default task-67                 TIMED_WAITING  5.82%     0.07%

    421 default task-66                 TIMED_WAITING  5.06%     0.06%

    415 default task-65                 TIMED_WAITING  4.27%     0.07%

    427 pool-24-thread-77               TIMED_WAITING  4.22%     0.02%

 Note: Only top 10 threads (according cpu load) are shown!

<<<

And after introducing 5ms of latency at the database server network interface using "tc", I immediately see this:

>>>

 JvmTop 0.8.0 alpha - 12:00:49,  amd64, 16 cpus, Linux 3.10.0-86, load avg 0.02

 http://code.google.com/p/jvmtop

 PID 10036: /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/jboss-modules.jar

 ARGS: -mp /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/modules org.jboss.a[...]

 VMARGS: -D[Server:spotdsno12] -D[pcid:316534345] -Xms2048m -Xmx8192m -XX:[...]

 VM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.8.0_144

 UP:  0:47m  #THR: 111  #THRPEAK: 187  #THRCREATED: 395  USER: apdsno12

 GC-Time:  0: 0m   #GC-Runs: 174       #TotalLoadedClasses: 33673

 CPU: 21.85% GC:  0.00% HEAP:2933m /8192m NONHEAP: 294m /1520m

  TID   NAME                                    STATE    CPU  TOTALCPU BLOCKEDBY

    351 pool-24-thread-44                    RUNNABLE 40.37%     2.13%

    318 pool-24-thread-20               TIMED_WAITING 40.35%     2.20%

    406 pool-24-thread-65               TIMED_WAITING 37.40%     1.30%

    388 pool-24-thread-47               TIMED_WAITING 36.59%     2.06%

    409 pool-24-thread-68                    RUNNABLE 33.47%     1.29%

    329 pool-24-thread-31               TIMED_WAITING 31.20%     2.11%

    349 pool-24-thread-36                    RUNNABLE 13.69%     2.23%

    396 pool-24-thread-60                    RUNNABLE 13.64%     2.21%

    410 pool-24-thread-69                    RUNNABLE 10.64%     1.28%

    371 default task-38                 TIMED_WAITING 10.04%     1.43%

 Note: Only top 10 threads (according cpu load) are shown!

<<<

The thread dump from jstack at that moment shows something like this for a "pool-24-thread" that is in RUNNABLE state:

>>>

"pool-24-thread-24" #358 prio=5 os_prio=0 tid=0x000000000f20c000 nid=0x2a4c runnable [0x00007f88230d7000]

   java.lang.Thread.State: RUNNABLE

        at java.lang.Thread.yield(Native Method)

        at com.conversantmedia.util.concurrent.Condition.progressiveYield(Condition.java:68)

        at com.conversantmedia.util.concurrent.AbstractWaitingCondition.await(AbstractWaitingCondition.java:144)

        at com.conversantmedia.util.concurrent.PushPullBlockingQueue.take(PushPullBlockingQueue.java:193)

        at org.geotools.renderer.lite.StreamingRenderer$RenderingBlockingQueue.take(StreamingRenderer.java:3823)

        ...

<<<

  And the code for Condition.progressiveYield() is:

>>>

     static int progressiveYield(final int n) {

        if(n > 500) {

            if(n<1000) {

                // "randomly" yield 1:8

                if((n & 0x7) == 0) {

                    LockSupport.parkNanos(PARK_TIMEOUT);

                } else {

                    onSpinWait();

                }

            } else if(n<MAX_PROG_YIELD) {

                // "randomly" yield 1:4

                if((n & 0x3) == 0) {

                    Thread.yield();

                } else {

                    onSpinWait();

                }

            } else {

                Thread.yield();

                return n;

            }

        } else {

            onSpinWait();

        }

        return n+1;

    }

    static void onSpinWait() {

        // Java 9 hint for spin waiting PAUSE instruction

        //http://openjdk.java.net/jeps/285

        // Thread.onSpinWait();

    }

<<<

So, it seems like the Conversant Disruptor (version 1.2.13) is doing some "busy-wait" here. Please correct me if this is not the case.

Regards,

Joao

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[geowolf]

On Sat, Feb 9, 2019 at 7:53 PM João Loureiro Junior <[hidden email]> wrote:

The thread dump from jstack at that moment shows something like this for a "pool-24-thread" that is in RUNNABLE state:

>>>

"pool-24-thread-24" #358 prio=5 os_prio=0 tid=0x000000000f20c000 nid=0x2a4c runnable [0x00007f88230d7000]

   java.lang.Thread.State: RUNNABLE

        at java.lang.Thread.yield(Native Method)

        at com.conversantmedia.util.concurrent.Condition.progressiveYield(Condition.java:68)

        at com.conversantmedia.util.concurrent.AbstractWaitingCondition.await(AbstractWaitingCondition.java:144)

        at com.conversantmedia.util.concurrent.PushPullBlockingQueue.take(PushPullBlockingQueue.java:193)

        at org.geotools.renderer.lite.StreamingRenderer$RenderingBlockingQueue.take(StreamingRenderer.java:3823)

        ...

<<<

This is intersting, but a jstack may show a transitory condition, a profiler output would be better.

In the previous mail you said ". It seems like that extra CPU is spent by the Oracle JDBC driver calls (as evidenced by Yourkit)",

while the disruptor usage is in the renderer and it's independent of the data source.

The disruptor dependency was added to avoid a scalability network, but I was playing with very large datasets

(millions of records), painting a good bunch of them (heavy multilayer map, OSM like), and with fast data sources

(shapefiles/postgis). I could imagine seeing a busy wait in case the data source is very slow, and at the same time,

returning very few records to paint.

However, a mere 5ms delay does not quite match a "very slow" delay.

If you want to experiment, you might look at reverting this commit in gt-render:

https://github.com/geotools/geotools/commit/7d508f1016a2a8ce51c42f6785a14625e2edbe26

https://osgeo-org.atlassian.net/browse/GEOT-6100

Or check if there are other configurable waiting modes in the disruptor.

If it helps in you case, while knowing that the switch to disruptor helped in another, maybe you could

make a PR adding a switch to decide which blocking queue to use depending on a configuration flag

(could be a system variable), or maybe there is a configuration of the disruptor that provides the

best of both worlds.

I don't have working hours to check this futher, but I'm pretty curious, so let me know what you find out!

Cheers

Andrea

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[geowolf]

On Sat, Feb 9, 2019 at 10:28 PM Andrea Aime <[hidden email]> wrote:

The disruptor dependency was added to avoid a scalability network

"a scalability issue"

(must learn to re-read mails before sending them!... or maybe not reply on Saturday night at 10:30pm)

Cheers

Andrea

==

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[loureiro]

Thanks Andrea, I will try that and follow up on the dev list.

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[geowolf]

Hi,

I am doing some benchmarks against a PostgreSQL data source and thought back about this issue.

The disruptor showed up in my profiles as well, not much, but was there. I changed the StreamingRenderer

to use a blocking variant of the same disruptor queue and got a bit less CPU usage, the requests

did not become faster, but the free CPU allowed a few more concurrent requests to be snuck in,

allowing for better throughput in a load test.

I've added that change along with a bunch of others to speed up rendering performance of large maps,

with several layers and complex symbology, from a PostGIS source (with some changes being

datastore independent) that hopefully will land on master (dev series, 2.16.x) in a few days.

Cheers

Andrea

On Mon, Feb 11, 2019 at 7:30 AM João Loureiro Junior <[hidden email]> wrote:

Thanks Andrea, I will try that and follow up on the dev list.

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

--


_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[loureiro]

Hi Andrea

I looked again at the YourKit profile I had taken during the tests but, for some reason, the Disruptor methods do not show up there. That is very starnge, but I did not have time to investigate it further. I did as you suggested and added an option to disable the Disruptor PushPullBlockingQueue and revert to the Java concurrent ArrayBlockingQueue (patch below). I run the tests again with the (slow) Oracle datasource and the results were way better, like only half the CPU previously required.

Good to know that you added some more performance improvements! What other Disruptor queue variant you changed to? As far as I understood from the Disruptor documentation, the PushPullBlockingQueue is the most efficient variant that is fully compatible with the Java BlockingQueue interface.

I think, at least in our scenarios, the previous implementation will be required anyway. Do you think you could incorporate the patch below as well? I could try to do a PR, but I have never done that before and would first need to understand the GeoTools development process.

Regards,

Joao 

>>>

diff --git a/modules/library/render/src/main/java/org/geotools/renderer/lite/StreamingRenderer.java b/modules/library/render/src/main/java/org/geotools/renderer/lite/StreamingRenderer.java

index 7ecd12629e..4c1fc242a8 100644

--- a/modules/library/render/src/main/java/org/geotools/renderer/lite/StreamingRenderer.java

+++ b/modules/library/render/src/main/java/org/geotools/renderer/lite/StreamingRenderer.java

@@ -44,6 +44,7 @@ import java.util.List;

 import java.util.Map;

 import java.util.Set;

 import java.util.Spliterator;

+import java.util.concurrent.ArrayBlockingQueue;

 import java.util.concurrent.BlockingQueue;

 import java.util.concurrent.CopyOnWriteArrayList;

 import java.util.concurrent.ExecutorService;

@@ -185,6 +186,10 @@ public class StreamingRenderer implements GTRenderer {

     private static final int defaultMaxFiltersToSendToDatastore = 5; // default

+    private static final boolean DISABLE_DISRUPTOR =

+            Boolean.parseBoolean(

+                    System.getProperty("org.geotools.renderer.lite.disableDisruptor", "false"));

+

     /**

      * Computes the scale as the ratio between map distances and real world distances, assuming

      * 90dpi and taking into consideration projection deformations and actual earth shape. <br>

@@ -3765,10 +3770,14 @@ public class StreamingRenderer implements GTRenderer {

     public class RenderingBlockingQueue implements BlockingQueue<RenderingRequest> {

         private static final long serialVersionUID = 4908029658595573833L;

-        PushPullBlockingQueue<RenderingRequest> delegate;

+        BlockingQueue<RenderingRequest> delegate;

         public RenderingBlockingQueue(int capacity) {

-            this.delegate = new PushPullBlockingQueue<>(capacity);

+            if (DISABLE_DISRUPTOR) {

+                this.delegate = new ArrayBlockingQueue<>(capacity);

+            } else {

+                this.delegate = new PushPullBlockingQueue<>(capacity);

+            }

         }

         @Override

<<<

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[geowolf]

On Fri, Feb 15, 2019 at 4:12 PM João Loureiro Junior <[hidden email]> wrote:

Hi Andrea

I looked again at the YourKit profile I had taken during the tests but, for some reason, the Disruptor methods do not show up there. That is very starnge, but I did not have time to investigate it further. I did as you suggested and added an option to disable the Disruptor PushPullBlockingQueue and revert to the Java concurrent ArrayBlockingQueue (patch below). I run the tests again with the (slow) Oracle datasource and the results were way better, like only half the CPU previously required.

Good to know that you added some more performance improvements! What other Disruptor queue variant you changed to? As far as I understood from the Disruptor documentation, the PushPullBlockingQueue is the most efficient variant that is fully compatible with the Java BlockingQueue interface.

I basically switched it to use the blocking mode right away, instead of the current mode, which does an active spin for a little while and then

 

I think, at least in our scenarios, the previous implementation will be required anyway. Do you think you could incorporate the patch below as well? I could try to do a PR, but I have never done that before and would first need to understand the GeoTools development process.

I believe the above change will already solve the issue for you too, if it does I'd rather have less moving parts/ifs around.

Can you try to just use the Disruptor queue with this "less than one line" change?

this.delegate = new PushPullBlockingQueue<>(capacity, SpinPolicy.BLOCKING);

 

Cheers

Andrea

==

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users

[loureiro]

Hi Andrea, I run the tests again with your fix and it seems to give the same result as using the Java concurrent classes, i.e., the Oracle latency does not seem to affect the GeoServer CPU usage anymore!

Best regards,

Joao 

_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:
- Earning your support instead of buying it, but Ian Turton: http://www.ianturton.com/talks/foss4g.html#/
- The GeoServer user list posting guidelines: http://geoserver.org/comm/userlist-guidelines.html

If you want to request a feature or an improvement, also see this: https://github.com/geoserver/geoserver/wiki/Successfully-requesting-and-integrating-new-features-and-improvements-in-GeoServer


[hidden email]
https://lists.sourceforge.net/lists/listinfo/geoserver-users