CFHTTP calls seem to have too much OSGI overhead

Description

I'm working with a client who has a Lucee app which never touches the DB directly. Instead, all data is fetched from back end microservices via the CFHTTP tag. Even though these backend services return in only a few ms, their site is running more slowly than they would like and has very high CPU usage. FusionReactor shows most all of the request time being related to the CFHTTP calls.

I spent quite a while looking through FusionReactor and verifying Lucee settings, etc. I have also created a basic repro case locally where I can see the same two stack traces that kept cropping up again and again. One is from the template that makes the CFHTTP call and the second is from the actual thread that CFHTTP creates to perform the underlying HTTP request.

In both cases, the threads are loading OSGI classes related to the apache.commons./logging.LogFactory.getLog() call. I'm not sure what this call is loading, but it's from inside the Apache HTTP library and it seems to be taking a majority of the time for the HTTP calls. Can we identify what these Felix class loading calls are and why they seem to be weighing down the CFHTTP calls under load?

Example stack trace 1, found often in the page that makes the CFHTTP call

Example stack trace 2, found often in the thread that actually makes the HTTP connection

I have created a sample setup using CommandBox servers to test performance I created

  • a simple API site that returned random sizes of JSON documents from 100KB to 500KB

  • A simple site that made 6 CFHTTP calls to the API and deserialized each JSON

  • I then used a simple JMeter script with 5 threads to hit the site and monitored with FusionReactor

I tested the following combinations

  • 4.5.5 java 8 u282

  • 5.3.7 on java 11.0.10+9

  • 5.3.7 on java 8 u282

  • 5.3.8-snapshot on java 11.0.10+9

  • Adobe 2021 java 8 u282

I have attached a zip file with the test files I used. I used CommandBox to start a single API server and hit /api.cfm and then I started a second site server which I hit the /index.cfm in. This was mostly just to separate the performance of the two. I used the 'server start' commands in CommandBox to dial in the Lucee and Java versions for each test.

Here were my results

4.5.5 java 8 u282
average time 105 ms with no load
average time 130 ms under load
38 requests per sec with 5 threads

5.3.7 java 11.0.10+9
average time 150 ms with no load
average time 230 ms under load
22 requests per sec with 5 threads

5.3.7 java 8 u282
average time 150 ms with no load
average time 200 ms under load
25 requests per sec with 5 threads

5.3.8 java 11.0.10+9
average time 150 ms with no load
average time 230 ms under load
22 requests per sec with 5 threads

Adobe 2021 java 8 u282
average time 75 ms with no load
average time 100 ms under load
47 requests per sec with 5 threads

You'll notice that Lucee 4.5.5 was FASTER than Lucee 5.x. This slowdown is no doubt related to the overhead of OSGI which is why you see "felix" in the stack traces.
I also noted that Java 8 seems to still have a small performance benefit over java 11. It had a slightly lower request time and slightly higher throughput.

And finally, Adobe ColdFusion 2021 is even faster than Lucee 4.x!!! Remember, 2021 uses OSGI too, just like Lucee. That test screamed with nearly twice the throughput.

Environment

None

Activity

Show:
Ben Nadel
8 days ago

I referenced this ticket in a blog post in which I was seeing ~ 70ms of unaccounted-for latency when I removed a CFHTTP call (and reimplemented logic inside the ColdFusion monolith). I’m wonder if that 70ms is the overhead that Brad has identified.

Alex Skinner
March 4, 2021, 12:06 AM

Great find Brad and really interesting

Brad Wood
March 2, 2021, 11:43 PM
Edited

Just for the sake of it-- In case anyone sees this and is on Lucee 5.2.9 still, the numbers are abysmal there. Upgrade immediately!

5.2.9 java 8 u282
average time 400 ms with no load
average time 700 ms under load
6 requests per sec with 5 threads

Assignee

Unassigned

Reporter

Brad Wood

Priority

New

Labels

Fix versions

None