You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@camel.apache.org by Claus Ibsen <cl...@gmail.com> on 2023/01/16 20:09:59 UTC
Re: Upgrading from 2.24.2 to 3.14.7 - xtokenize performance
Hi Steven
Sorry we dont have time to investigate this very much.
Can you take a look at TokenXMLExpressionIterator and maybe performance
test this class, as that is the "brain" of xtokenize.
Maybe its this commit that makes it slower
https://github.com/apache/camel/commit/713f2194654b50b532750d9704b3d38be17f298b
On Thu, Dec 29, 2022 at 2:52 PM Steven George <st...@hotmail.com>
wrote:
> Hi Camel Users,
>
> I'm upgrading an application that uses Camel 2.24.2/Spring Boot/JDK8
> to the latest JDK8 compatible Camel LTS version 3.14.7.
>
> The application processes large XML files, using the xtokenize
> language and the com.fasterxml.woodstox::woodstox-core::6.4.0 parser.
>
> I ran into a significant performance issue after the upgrade. I
> located the bottleneck at the splitter, which splits the XML payload
> using xtokenize and streaming=true. The following is a simple
> benchmark test:
>
> (Test XML file (zipped) can be downloaded from here:
> https://data.fca.org.uk/artefacts/FIRDS/DLTINS_20221228_01of01.zip)
>
> @Component
> public class MyRoute extends RouteBuilder {
>
> @Override
> public void configure() {
>
> from("file://C:/dev/temp?fileName=DLTINS_20221228_01of01.xml&noop=true")
> .split().xtokenize("//document:FinInstrm", new
> Namespaces("document",
> "urn:iso:std:iso:20022:tech:xsd:auth.036.001.03")).streaming()
>
>
> .to("log:DELTA?level=INFO&groupInterval=1000&groupDelay=1000&groupActiveOnly=false");
> }
>
> }
>
> Processor: Intel(R) Core(TM) i7-8750H CPU @ 2.20GHz 2.21 GHz
> RAM: 16.0 GB
> VM args: -Xms2g -Xmx2g -XX:+UseSerialGC (though regardless of various
> GC and heap configurations, the result pattern below remains the same)
>
> Results Summary:
>
> Camel Version | JDK | Messages per/sec peek average |
> --------------|---------------|--------------------------------|
> 2.24.2 | jdk1.8.0_333 | 45,425.551 |
> 3.14.7 | jdk1.8.0_333 | 37,538.577 |
> 3.14.7 | jdk-11.0.16.1 | 32,718.978 |
> 3.20.0 | jdk-11.0.16.1 | 31,397.756 |
>
> The results above show that there is a drop in throughput between
> versions 2.24.2 and 3.14.7.
> Upgrading to Java 11 incurs a further performance penalty in 3.14.7
> and the latest Camel version 3.20.0.
> 3.14.7 v 3.20.0 results on Java 11 are negligible.
>
> Replacing the xtokenize with a simple .tokenize("\n") shows negligible
> results across versions, so the problem appears to be with xtokenize.
>
> Is there something fundamental I'm missing in my configuration between
> v2 and v3 (my project/pom is very simple)? I was also surprised to see
> such a performance hit between Java 8 and 11.
>
> Thanks!
>
> Steve
>
> Full results below:
>
> Camel Version | JDK | Messages per/sec peek average |
> --------------|---------------|--------------------------------|
> 2.24.2 | jdk1.8.0_333 | 45,425.551 |
>
> "C:\Program Files\Java\jdk1.8.0_333\bin\java.exe" -Xms2g -Xmx2g
> -XX:+UseSerialGC -XX:+PrintCommandLineFlags
> -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote
> -XX:InitialHeapSize=2147483648 -XX:+ManagementServer
> -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags
> -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers
> -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation
> -XX:+UseSerialGC
>
> . ____ _ __ _ _
> /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
> ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
> \\/ ___)| |_)| | | | | || (_| | ) ) ) )
> ' |____| .__|_| |_|_| |_\__, | / / / /
> =========|_|==============|___/=/_/_/_/
> :: Spring Boot :: (v2.1.1.RELEASE)
>
> 2022-12-29 11:32:50.645 INFO 34432 --- [ main]
> com.example.Application : Starting Application on ...
> 2022-12-29 11:32:50.647 INFO 34432 --- [ main]
> com.example.Application : No active profile set,
> falling back to default profiles: default
> 2022-12-29 11:32:51.229 INFO 34432 --- [ main]
> trationDelegate$BeanPostProcessorChecker : Bean
> 'org.apache.camel.spring.boot.CamelAutoConfiguration' of type
>
> [org.apache.camel.spring.boot.CamelAutoConfiguration$$EnhancerBySpringCGLIB$$34fe54d3]
> is not eligible for getting processed by all BeanPostProcessors (for
> example: not eligible for auto-proxying)
> 2022-12-29 11:32:51.407 INFO 34432 --- [ main]
> o.a.c.i.converter.DefaultTypeConverter : Type converters loaded
> (core: 195, classpath: 1)
> 2022-12-29 11:32:51.596 INFO 34432 --- [ main]
> o.a.camel.spring.boot.RoutesCollector : Loading additional Camel
> XML routes from: classpath:camel/*.xml
> 2022-12-29 11:32:51.596 INFO 34432 --- [ main]
> o.a.camel.spring.boot.RoutesCollector : Loading additional Camel
> XML rests from: classpath:camel-rest/*.xml
> 2022-12-29 11:32:51.600 INFO 34432 --- [ main]
> o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
> (CamelContext: camel-1) is starting
> 2022-12-29 11:32:51.601 INFO 34432 --- [ main]
> o.a.c.m.ManagedManagementStrategy : JMX is enabled
> 2022-12-29 11:32:51.704 INFO 34432 --- [ main]
> o.a.camel.spring.SpringCamelContext : StreamCaching is not in
> use. If using streams then its recommended to enable stream caching.
> See more details at http://camel.apache.org/stream-caching.html
> 2022-12-29 11:32:51.706 INFO 34432 --- [ main]
> o.a.camel.component.file.FileEndpoint : Endpoint is configured with
> noop=true so forcing endpoint to be idempotent as well
> 2022-12-29 11:32:51.707 INFO 34432 --- [ main]
> o.a.camel.component.file.FileEndpoint : Using default memory based
> idempotent repository with cache max size: 1000
> 2022-12-29 11:32:51.711 INFO 34432 --- [ main]
> o.a.camel.processor.ThroughputLogger : Scheduling throughput log
> to run every 1000 millis.
> 2022-12-29 11:32:51.732 INFO 34432 --- [ main]
> o.a.camel.spring.boot.RoutesCollector : Starting
> CamelMainRunController to ensure the main thread keeps running
> 2022-12-29 11:32:51.736 INFO 34432 --- [ main]
> o.a.camel.spring.SpringCamelContext : Route: route1 started and
> consuming from:
> file://C:/dev/temp?fileName=DLTINS_20221228_01of01.xml&noop=true
> 2022-12-29 11:32:51.736 INFO 34432 --- [ main]
> o.a.camel.spring.SpringCamelContext : Total 1 routes, of which 1
> are started
> 2022-12-29 11:32:51.737 INFO 34432 --- [ main]
> o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
> (CamelContext: camel-1) started in 0.136 seconds
> 2022-12-29 11:32:51.740 INFO 34432 --- [ main]
> com.example.Application : Started Application in
> 1.313 seconds (JVM running for 1.966)
> 2022-12-29 11:32:53.720 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 32899 new messages, with total
> 32899 so far. Last group took: 930 millis which is: 35,375.269
> messages per second. average: 35,375.269
> 2022-12-29 11:32:54.717 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 46507 new messages, with total
> 79406 so far. Last group took: 1001 millis which is: 46,460.539
> messages per second. average: 41,121.699
> 2022-12-29 11:32:55.714 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 46640 new messages, with total
> 126046 so far. Last group took: 997 millis which is: 46,780.341
> messages per second. average: 43,048.497
> 2022-12-29 11:32:56.725 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 47767 new messages, with total
> 173813 so far. Last group took: 1011 millis which is: 47,247.28
> messages per second. average: 44,126.174
> 2022-12-29 11:32:57.717 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 43656 new messages, with total
> 217469 so far. Last group took: 992 millis which is: 44,008.065
> messages per second. average: 44,102.413
> 2022-12-29 11:32:58.714 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 46344 new messages, with total
> 263813 so far. Last group took: 997 millis which is: 46,483.45
> messages per second. average: 44,502.868
> 2022-12-29 11:32:59.715 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 47372 new messages, with total
> 311185 so far. Last group took: 1001 millis which is: 47,324.675
> messages per second. average: 44,910.521
> 2022-12-29 11:33:00.727 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 47083 new messages, with total
> 358268 so far. Last group took: 1012 millis which is: 46,524.704
> messages per second. average: 45,116.232
> 2022-12-29 11:33:01.724 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 46190 new messages, with total
> 404458 so far. Last group took: 997 millis which is: 46,328.987
> messages per second. average: 45,251.51
> 2022-12-29 11:33:02.719 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 46754 new messages, with total
> 451212 so far. Last group took: 995 millis which is: 46,988.945
> messages per second. average: 45,425.551
> 2022-12-29 11:33:03.724 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 21006 new messages, with total
> 472218 so far. Last group took: 1005 millis which is: 20,901.493
> messages per second. average: 43,172.244
> 2022-12-29 11:33:04.726 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1002 millis which is: 0 messages per
> second. average: 39,549.246
> 2022-12-29 11:33:05.725 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 999 millis which is: 0 messages per
> second. average: 36,495.711
> 2022-12-29 11:33:06.724 INFO 34432 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 999 millis which is: 0 messages per
> second. average: 33,879.897
> 2022-12-29 11:33:07.344 INFO 34432 --- [ngupInterceptor]
> o.a.c.m.MainSupport$HangupInterceptor : Received hang up - stopping
> the main instance.
> 2022-12-29 11:33:07.345 INFO 34432 --- [ngupInterceptor]
> o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
> (CamelContext: camel-1) is shutting down
> 2022-12-29 11:33:07.346 INFO 34432 --- [ngupInterceptor]
> o.a.camel.impl.DefaultShutdownStrategy : Starting to graceful
> shutdown 1 routes (timeout 300 seconds)
> 2022-12-29 11:33:07.348 INFO 34432 --- [ - ShutdownTask]
> o.a.camel.impl.DefaultShutdownStrategy : Route: route1 shutdown
> complete, was consuming from:
> file://C:/dev/temp?fileName=DLTINS_20221228_01of01.xml&noop=true
> 2022-12-29 11:33:07.348 INFO 34432 --- [ngupInterceptor]
> o.a.camel.impl.DefaultShutdownStrategy : Graceful shutdown of 1
> routes completed in 0 seconds
> 2022-12-29 11:33:07.351 INFO 34432 --- [ngupInterceptor]
> o.a.camel.main.MainLifecycleStrategy : CamelContext: camel-1 has
> been shutdown, triggering shutdown of the JVM.
> 2022-12-29 11:33:07.354 INFO 34432 --- [ngupInterceptor]
> o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
> (CamelContext: camel-1) uptime 15.754 seconds
> 2022-12-29 11:33:07.354 INFO 34432 --- [ngupInterceptor]
> o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
> (CamelContext: camel-1) is shutdown in 0.009 seconds
>
> Process finished with exit code 130
>
> Camel Version | JDK | Messages per/sec peek average |
> --------------|---------------|--------------------------------|
> 3.14.7 | jdk1.8.0_333 | 37,538.577 |
>
> "C:\Program Files\Java\jdk1.8.0_333\bin\java.exe" -Xms2g -Xmx2g
> -XX:+UseSerialGC -XX:+PrintCommandLineFlags
> -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote
> -XX:InitialHeapSize=2147483648 -XX:+ManagementServer
> -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags
> -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers
> -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation
> -XX:+UseSerialGC
>
> . ____ _ __ _ _
> /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
> ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
> \\/ ___)| |_)| | | | | || (_| | ) ) ) )
> ' |____| .__|_| |_|_| |_\__, | / / / /
> =========|_|==============|___/=/_/_/_/
> :: Spring Boot :: (v2.6.13)
>
> 2022-12-29 11:38:02.020 INFO 10044 --- [ main]
> com.example.Application : Starting Application using
> Java 1.8.0_333 on ...
> 2022-12-29 11:38:02.022 INFO 10044 --- [ main]
> com.example.Application : No active profile set,
> falling back to 1 default profile: "default"
> 2022-12-29 11:38:03.052 INFO 10044 --- [ main]
> o.a.camel.component.file.FileEndpoint : Endpoint is configured with
> noop=true so forcing endpoint to be idempotent as well
> 2022-12-29 11:38:03.053 INFO 10044 --- [ main]
> o.a.camel.component.file.FileEndpoint : Using default memory based
> idempotent repository with cache max size: 1000
> 2022-12-29 11:38:03.061 INFO 10044 --- [ main]
> o.a.c.s.processor.ThroughputLogger : Scheduling throughput
> logger to run every 1000 millis.
> 2022-12-29 11:38:03.066 INFO 10044 --- [ main]
> c.s.b.CamelSpringBootApplicationListener : Starting
> CamelMainRunController to ensure the main thread keeps running
> 2022-12-29 11:38:03.072 INFO 10044 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Routes startup (total:1
> started:1)
> 2022-12-29 11:38:03.072 INFO 10044 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Started route1
> (file://C:/dev/temp)
> 2022-12-29 11:38:03.072 INFO 10044 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) started in 155ms (build:23ms init:123ms start:9ms)
> 2022-12-29 11:38:03.076 INFO 10044 --- [ main]
> com.example.Application : Started Application in
> 1.299 seconds (JVM running for 2.08)
> 2022-12-29 11:38:05.071 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 30359 new messages, with total
> 30359 so far. Last group took: 958 millis which is: 31,689.979
> messages per second. average: 31,689.979
> 2022-12-29 11:38:06.066 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 37532 new messages, with total
> 67891 so far. Last group took: 997 millis which is: 37,644.935
> messages per second. average: 34,726.854
> 2022-12-29 11:38:07.061 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38117 new messages, with total
> 106008 so far. Last group took: 995 millis which is: 38,308.543
> messages per second. average: 35,934.915
> 2022-12-29 11:38:08.073 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38507 new messages, with total
> 144515 so far. Last group took: 1012 millis which is: 38,050.395
> messages per second. average: 36,475.265
> 2022-12-29 11:38:09.073 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 37900 new messages, with total
> 182415 so far. Last group took: 1000 millis which is: 37,900 messages
> per second. average: 36,762.394
> 2022-12-29 11:38:10.069 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38121 new messages, with total
> 220536 so far. Last group took: 996 millis which is: 38,274.096
> messages per second. average: 37,015.106
> 2022-12-29 11:38:11.068 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38156 new messages, with total
> 258692 so far. Last group took: 999 millis which is: 38,194.194
> messages per second. average: 37,184.419
> 2022-12-29 11:38:12.076 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38802 new messages, with total
> 297494 so far. Last group took: 1008 millis which is: 38,494.048
> messages per second. average: 37,350.157
> 2022-12-29 11:38:13.075 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38235 new messages, with total
> 335729 so far. Last group took: 999 millis which is: 38,273.273
> messages per second. average: 37,453.034
> 2022-12-29 11:38:14.073 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 37768 new messages, with total
> 373497 so far. Last group took: 998 millis which is: 37,843.687
> messages per second. average: 37,492.17
> 2022-12-29 11:38:15.064 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 36979 new messages, with total
> 410476 so far. Last group took: 991 millis which is: 37,314.834
> messages per second. average: 37,476.125
> 2022-12-29 11:38:16.061 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 38110 new messages, with total
> 448586 so far. Last group took: 997 millis which is: 38,224.674
> messages per second. average: 37,538.577
> 2022-12-29 11:38:17.072 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 23632 new messages, with total
> 472218 so far. Last group took: 1011 millis which is: 23,374.876
> messages per second. average: 36,433.763
> 2022-12-29 11:38:18.064 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 992 millis which is: 0 messages per
> second. average: 33,843.475
> 2022-12-29 11:38:19.070 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1006 millis which is: 0 messages per
> second. average: 31,567.484
> 2022-12-29 11:38:20.067 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 997 millis which is: 0 messages per
> second. average: 29,595.011
> 2022-12-29 11:38:21.065 INFO 10044 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 998 millis which is: 0 messages per
> second. average: 27,852.896
> 2022-12-29 11:38:21.242 INFO 10044 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) shutting down (timeout:45s)
> 2022-12-29 11:38:21.246 INFO 10044 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Routes stopped (total:1
> stopped:1)
> 2022-12-29 11:38:21.246 INFO 10044 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Stopped route1
> (file://C:/dev/temp)
> 2022-12-29 11:38:21.248 INFO 10044 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) shutdown in 6ms (uptime:18s185ms)
>
> Process finished with exit code 130
>
>
>
> Camel Version | JDK | Messages per/sec peek average |
> --------------|---------------|--------------------------------|
> 3.14.7 | jdk-11.0.16.1 | 32,718.978 |
>
> "C:\Program Files\Java\jdk-11.0.16.1\bin\java.exe" -Xms2g -Xmx2g
> -XX:+UseSerialGC -XX:+PrintCommandLineFlags
> -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote
> -XX:InitialHeapSize=2147483648 -XX:+ManagementServer
> -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags
> -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache
> -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers
> -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation
> -XX:+UseSerialGC
>
> . ____ _ __ _ _
> /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
> ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
> \\/ ___)| |_)| | | | | || (_| | ) ) ) )
> ' |____| .__|_| |_|_| |_\__, | / / / /
> =========|_|==============|___/=/_/_/_/
> :: Spring Boot :: (v2.6.13)
>
> 2022-12-29 11:36:40.142 INFO 32868 --- [ main]
> com.example.Application : Starting Application using
> Java 11.0.16.1 on ...
> 2022-12-29 11:36:40.144 INFO 32868 --- [ main]
> com.example.Application : No active profile set,
> falling back to 1 default profile: "default"
> 2022-12-29 11:36:41.158 INFO 32868 --- [ main]
> o.a.camel.component.file.FileEndpoint : Endpoint is configured with
> noop=true so forcing endpoint to be idempotent as well
> 2022-12-29 11:36:41.158 INFO 32868 --- [ main]
> o.a.camel.component.file.FileEndpoint : Using default memory based
> idempotent repository with cache max size: 1000
> 2022-12-29 11:36:41.169 INFO 32868 --- [ main]
> o.a.c.s.processor.ThroughputLogger : Scheduling throughput
> logger to run every 1000 millis.
> 2022-12-29 11:36:41.174 INFO 32868 --- [ main]
> c.s.b.CamelSpringBootApplicationListener : Starting
> CamelMainRunController to ensure the main thread keeps running
> 2022-12-29 11:36:41.180 INFO 32868 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Routes startup (total:1
> started:1)
> 2022-12-29 11:36:41.180 INFO 32868 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Started route1
> (file://C:/dev/temp)
> 2022-12-29 11:36:41.180 INFO 32868 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) started in 170ms (build:27ms init:135ms start:8ms)
> 2022-12-29 11:36:41.185 INFO 32868 --- [ main]
> com.example.Application : Started Application in
> 1.287 seconds (JVM running for 2.139)
> 2022-12-29 11:36:43.171 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 26605 new messages, with total
> 26605 so far. Last group took: 922 millis which is: 28,855.748
> messages per second. average: 28,855.748
> 2022-12-29 11:36:44.184 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 31150 new messages, with total
> 57755 so far. Last group took: 1014 millis which is: 30,719.921
> messages per second. average: 29,832.128
> 2022-12-29 11:36:45.177 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 32432 new messages, with total
> 90187 so far. Last group took: 993 millis which is: 32,660.624
> messages per second. average: 30,791.055
> 2022-12-29 11:36:46.184 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33363 new messages, with total
> 123550 so far. Last group took: 1007 millis which is: 33,131.082
> messages per second. average: 31,389.736
> 2022-12-29 11:36:47.184 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33861 new messages, with total
> 157411 so far. Last group took: 1000 millis which is: 33,861 messages
> per second. average: 31,890.397
> 2022-12-29 11:36:48.180 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33079 new messages, with total
> 190490 so far. Last group took: 996 millis which is: 33,211.847
> messages per second. average: 32,112.272
> 2022-12-29 11:36:49.180 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33899 new messages, with total
> 224389 so far. Last group took: 1000 millis which is: 33,899 messages
> per second. average: 32,370.023
> 2022-12-29 11:36:50.177 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33205 new messages, with total
> 257594 so far. Last group took: 997 millis which is: 33,304.915
> messages per second. average: 32,487.577
> 2022-12-29 11:36:51.172 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33114 new messages, with total
> 290708 so far. Last group took: 995 millis which is: 33,280.402
> messages per second. average: 32,575.975
> 2022-12-29 11:36:52.172 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33193 new messages, with total
> 323901 so far. Last group took: 1000 millis which is: 33,193 messages
> per second. average: 32,638.15
> 2022-12-29 11:36:53.185 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 33649 new messages, with total
> 357550 so far. Last group took: 1013 millis which is: 33,217.177
> messages per second. average: 32,691.78
> 2022-12-29 11:36:54.183 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 32951 new messages, with total
> 390501 so far. Last group took: 998 millis which is: 33,017.034
> messages per second. average: 32,718.978
> 2022-12-29 11:36:55.181 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 32260 new messages, with total
> 422761 so far. Last group took: 998 millis which is: 32,324.649
> messages per second. average: 32,688.549
> 2022-12-29 11:36:56.171 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 32503 new messages, with total
> 455264 so far. Last group took: 990 millis which is: 32,831.313
> messages per second. average: 32,698.7
> 2022-12-29 11:36:57.178 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 16954 new messages, with total
> 472218 so far. Last group took: 1007 millis which is: 16,836.147
> messages per second. average: 31,628.801
> 2022-12-29 11:36:58.182 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1004 millis which is: 0 messages per
> second. average: 29,635.873
> 2022-12-29 11:36:59.180 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 998 millis which is: 0 messages per
> second. average: 27,889.086
> 2022-12-29 11:37:00.182 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1002 millis which is: 0 messages per
> second. average: 26,330.88
> 2022-12-29 11:37:01.185 INFO 32868 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1003 millis which is: 0 messages per
> second. average: 24,936.262
> 2022-12-29 11:37:01.253 INFO 32868 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) shutting down (timeout:45s)
> 2022-12-29 11:37:01.259 INFO 32868 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Routes stopped (total:1
> stopped:1)
> 2022-12-29 11:37:01.259 INFO 32868 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Stopped route1
> (file://C:/dev/temp)
> 2022-12-29 11:37:01.260 INFO 32868 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.14.7
> (camel-1) shutdown in 7ms (uptime:20s88ms)
>
> Process finished with exit code 130
>
>
>
> Camel Version | JDK | Messages per/sec peek average |
> --------------|---------------|--------------------------------|
> 3.20.0 | jdk-11.0.16.1 | 31,397.756 |
>
> "C:\Program Files\Java\jdk-11.0.16.1\bin\java.exe" -Xms2g -Xmx2g
> -XX:+UseSerialGC -XX:+PrintCommandLineFlags
> -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote
> -XX:InitialHeapSize=2147483648 -XX:+ManagementServer
> -XX:MaxHeapSize=2147483648 -XX:+PrintCommandLineFlags
> -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache
> -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers
> -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation
> -XX:+UseSerialGC
>
> . ____ _ __ _ _
> /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
> ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
> \\/ ___)| |_)| | | | | || (_| | ) ) ) )
> ' |____| .__|_| |_|_| |_\__, | / / / /
> =========|_|==============|___/=/_/_/_/
> :: Spring Boot :: (v2.7.6)
>
> 2022-12-29 11:35:18.101 INFO 11444 --- [ main]
> com.example.Application : Starting Application using
> Java 11.0.16.1 on ...
> 2022-12-29 11:35:18.103 INFO 11444 --- [ main]
> com.example.Application : No active profile set,
> falling back to 1 default profile: "default"
> 2022-12-29 11:35:19.159 INFO 11444 --- [ main]
> o.a.camel.component.file.FileEndpoint : Endpoint is configured with
> noop=true so forcing endpoint to be idempotent as well
> 2022-12-29 11:35:19.159 INFO 11444 --- [ main]
> o.a.camel.component.file.FileEndpoint : Using default memory based
> idempotent repository with cache max size: 1000
> 2022-12-29 11:35:19.172 INFO 11444 --- [ main]
> o.a.c.s.processor.ThroughputLogger : Scheduling throughput
> logger to run every 1000 millis.
> 2022-12-29 11:35:19.176 INFO 11444 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.20.0
> (camel-1) is starting
> 2022-12-29 11:35:19.178 INFO 11444 --- [ main]
> c.s.b.CamelSpringBootApplicationListener : Starting
> CamelMainRunController to ensure the main thread keeps running
> 2022-12-29 11:35:19.178 INFO 11444 --- [inRunController]
> org.apache.camel.main.MainSupport : Apache Camel (Main) 3.20.0
> is starting
> 2022-12-29 11:35:19.186 INFO 11444 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Routes startup (started:1)
> 2022-12-29 11:35:19.187 INFO 11444 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Started route1
> (file://C:/dev/temp)
> 2022-12-29 11:35:19.187 INFO 11444 --- [ main]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.20.0
> (camel-1) started in 183ms (build:26ms init:147ms start:10ms)
> 2022-12-29 11:35:19.191 INFO 11444 --- [ main]
> com.example.Application : Started Application in
> 1.364 seconds (JVM running for 2.33)
> 2022-12-29 11:35:21.194 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 25565 new messages, with total
> 25565 so far. Last group took: 939 millis which is: 27,225.772
> messages per second. average: 27,225.772
> 2022-12-29 11:35:22.181 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 29169 new messages, with total
> 54734 so far. Last group took: 996 millis which is: 29,286.145
> messages per second. average: 28,286.305
> 2022-12-29 11:35:23.181 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31822 new messages, with total
> 86556 so far. Last group took: 1000 millis which is: 31,822 messages
> per second. average: 29,490.971
> 2022-12-29 11:35:24.183 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31574 new messages, with total
> 118130 so far. Last group took: 1002 millis which is: 31,510.978
> messages per second. average: 30,005.08
> 2022-12-29 11:35:25.184 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 32258 new messages, with total
> 150388 so far. Last group took: 1001 millis which is: 32,225.774
> messages per second. average: 30,455.245
> 2022-12-29 11:35:26.180 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31776 new messages, with total
> 182164 so far. Last group took: 996 millis which is: 31,903.614
> messages per second. average: 30,698.349
> 2022-12-29 11:35:27.179 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 32232 new messages, with total
> 214396 so far. Last group took: 999 millis which is: 32,264.264
> messages per second. average: 30,923.987
> 2022-12-29 11:35:28.177 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 32547 new messages, with total
> 246943 so far. Last group took: 998 millis which is: 32,612.224
> messages per second. average: 31,136.427
> 2022-12-29 11:35:29.177 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31793 new messages, with total
> 278736 so far. Last group took: 1000 millis which is: 31,793 messages
> per second. average: 31,209.943
> 2022-12-29 11:35:30.179 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 32089 new messages, with total
> 310825 so far. Last group took: 1002 millis which is: 32,024.95
> messages per second. average: 31,292.157
> 2022-12-29 11:35:31.175 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31462 new messages, with total
> 342287 so far. Last group took: 996 millis which is: 31,588.353
> messages per second. average: 31,319.151
> 2022-12-29 11:35:32.188 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 32665 new messages, with total
> 374952 so far. Last group took: 1013 millis which is: 32,245.805
> messages per second. average: 31,397.756
> 2022-12-29 11:35:33.185 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 30866 new messages, with total
> 405818 so far. Last group took: 997 millis which is: 30,958.877
> messages per second. average: 31,363.938
> 2022-12-29 11:35:34.176 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 31511 new messages, with total
> 437329 so far. Last group took: 991 millis which is: 31,797.175
> messages per second. average: 31,394.76
> 2022-12-29 11:35:35.181 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 30706 new messages, with total
> 468035 so far. Last group took: 1005 millis which is: 30,553.234
> messages per second. average: 31,338.132
> 2022-12-29 11:35:36.179 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 4183 new messages, with total
> 472218 so far. Last group took: 998 millis which is: 4,191.383
> messages per second. average: 29,637.733
> 2022-12-29 11:35:37.179 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 1000 millis which is: 0 messages per
> second. average: 27,887.439
> 2022-12-29 11:35:38.174 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 995 millis which is: 0 messages per
> second. average: 26,339.692
> 2022-12-29 11:35:39.173 INFO 11444 --- [hroughputLogger] DELTA
> : Received: 0 new messages, with total
> 472218 so far. Last group took: 999 millis which is: 0 messages per
> second. average: 24,949.437
> 2022-12-29 11:35:39.973 INFO 11444 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.20.0
> (camel-1) is shutting down (timeout:45s)
> 2022-12-29 11:35:39.978 INFO 11444 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Routes stopped (stopped:1)
> 2022-12-29 11:35:39.979 INFO 11444 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Stopped route1
> (file://C:/dev/temp)
> 2022-12-29 11:35:39.980 INFO 11444 --- [ionShutdownHook]
> o.a.c.impl.engine.AbstractCamelContext : Apache Camel 3.20.0
> (camel-1) shutdown in 7ms (uptime:20s)
>
> Process finished with exit code 130
>
--
Claus Ibsen
-----------------
@davsclaus
Camel in Action 2: https://www.manning.com/ibsen2