Clojurians Log v2

raised https://github.com/xtdb/xtdb/issues/4568 for us to take a look, cheers @chuck.cassel 🙂 🙏

in terms of more info - can you query:

psql -h localhost -U xtdb xtdb -c 'select `level`, trie_state, count(*) trie_count from xt.trie_stats'

psql --csv -h localhost -U xtdb xtdb -c 'select * exclude temporal_metadata from xt.trie_stats' > out.csv

oh, also, does this one have any more stack printed?

22:59:30.610 [DefaultDispatcher-worker-14] ERROR xtdb.util - Uncaught exception:
java.lang.IllegalStateException: AppendRecord would exceed the maximum allowed metered size of 1MiB, currently 1049854 bytes.
        at s2.types.AppendRecord$AppendRecordBuilder.build(AppendRecord.java:65)
        at chucklehead.xtdb.s2.S2Log$appendMessage$1.invokeSuspend(S2Log.kt:74)

ah man, this is a miss on our part - we're using Java Paths so that the local disk storage and local disk cache all use directories correctly, but those don't get replaced when the objects are sent remotely 😔

no worries, it "works" just fine. I just had to fall back from click-ops to the cli to clean things up afterwards.

trying to use xtdb-bench to shake out bugs in my S2 Log https://github.com/chucklehead-dev/s2-log and moved from WSL to native Windows at one point for memory reasons.

cool, yeah - this'll probably have impacts on mixed Windows/Unix clusters, if nothing else

oh, and maybe when you restart the node, I'd be surprised if it could pick up any existing blocks because I think it'll try to list a specific directory...?

raised https://github.com/xtdb/xtdb/issues/4548 for us to track it

> oh, and maybe when you restart the node, I'd be surprised if it could pick up any existing blocks because I think it'll try to list a specific directory...? maaaybe...I have seen some strange behavior when doing multiple bench runs without clearing out logs/storage that I've attributed to my code, but it would be nice to find out otherwise. I'll see about retesting in Linux.

> raised https://github.com/xtdb/xtdb/issues/4548 for us to track it thanks 🙏🏻 fyi it's not blocking me from anything critical, just trying to get this working for a side project

I tested back in WSL and one of my bugs did go away, on back-to-back runs of readings I was seeing a 10-minute freeze during the compact phase even though all the thread were reporting idle. That doesn't seem to happen in WSL.

The last one I don't think I can do anything about myself. When I do back-to-back runs of tpch with scale 0.01, the compactor eventually generates a log message larger than 1MB, which is currently a hard limit for S2 streams. I didn't think this would be a problem since the https://docs.xtdb.com/ops/config/log/kafka.html docs also mention a 1MB default, but they do say it's dependent on TX size. Could I have a bug that's causing an overly large log entry, or would this be a scenario where a large size would be expected?

yeah, this one definitely has nothing to do with restarting because I can also reproduce it from clean storage and trimmed log by using a larger scale factor like 0.05

> Task :tpch
22:58:53.259 [main] INFO  xtdb.bench.tpch - {:scale-factor 0.05}
22:58:53.262 [main] INFO  xtdb.bench - Running node from config file: #object[java.io.File 0x6db1b0c s2.yaml]
22:58:54.075 [main] INFO  xtdb.metrics - tagging all metrics with node-id: 10fde3db
22:58:54.120 [main] INFO  o.apache.arrow.memory.BaseAllocator - Debug mode disabled. Enable with the VM option -Darrow.memory.debug.allocator=true.
22:58:54.121 [main] INFO  o.a.a.m.DefaultAllocationManagerOption - allocation manager type not specified, using netty as the default type
22:58:54.123 [main] INFO  o.apache.arrow.memory.CheckAllocator - Using DefaultAllocationManager at memory-netty/18.3.0/48e3c2bc75c062a3d585f740c8a20ba4b0bd6b48/arrow-memory-netty-18.3.0.jar!/org/apache/arrow/memory/netty/DefaultAllocationManagerFactory.class
22:58:55.299 [main] INFO  chucklehead.xtdb.s2.S2Log - Opening S2 log at basin: xtdb-log, stream: xtdb-bench-express
22:58:56.009 [main] INFO  chucklehead.xtdb.s2.S2Log - Opened log with tail seq: 24289 and ts: 1750733869038
22:58:56.049 [DefaultDispatcher-worker-1] TRACE xtdb.compactor.Compactor - sending idle
22:58:56.092 [DefaultDispatcher-worker-2] INFO  chucklehead.xtdb.s2.S2Log - Starting new subscription at offset: 0
22:58:56.099 [main] INFO  xtdb.pgwire - Server started on port: 39067
22:58:56.103 [main] INFO  x.garbage_collector.GarbageCollector - Starting GarbageCollector with approxRunInterval: PT10M, blocksToKeep: 10
22:58:56.106 [main] INFO  xtdb.bench - Starting stage: :ingest
22:58:56.106 [main] INFO  xtdb.bench - Starting stage: :submit-docs
22:58:56.106 [main] INFO  xtdb.datasets.tpch - Transacting TPC-H tables...
22:59:04.610 [DefaultDispatcher-worker-7] TRACE xtdb.compactor.Compactor - wakey wakey
22:59:04.641 [DefaultDispatcher-worker-4] DEBUG xtdb.compactor.Compactor - compacting 'public/lineitem' '["l00-rc-b00"]' -> l01-rc-b00
22:59:04.641 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacting 'public/orders' '["l00-rc-b00"]' -> l01-rc-b00
22:59:04.641 [DefaultDispatcher-worker-1] DEBUG xtdb.compactor.Compactor - compacting 'xt/txs' '["l00-rc-b00"]' -> l01-rc-b00
22:59:04.642 [DefaultDispatcher-worker-7] DEBUG xtdb.compactor.Compactor - compacting 'public/customer' '["l00-rc-b00"]' -> l01-rc-b00
22:59:04.980 [DefaultDispatcher-worker-1] DEBUG xtdb.compactor.Compactor - compacted 'xt/txs' -> 'l01-rc-b00'
22:59:05.646 [DefaultDispatcher-worker-7] DEBUG xtdb.compactor.Compactor - compacted 'public/customer' -> 'l01-rc-b00'
22:59:06.550 [DefaultDispatcher-worker-4] DEBUG xtdb.compactor.Compactor - compacted 'public/lineitem' -> 'l01-rc-b00'
22:59:08.998 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacted 'public/orders' -> 'l01-rc-b00'
22:59:09.344 [DefaultDispatcher-worker-10] TRACE xtdb.compactor.Compactor - sending idle
22:59:11.267 [DefaultDispatcher-worker-6] TRACE xtdb.compactor.Compactor - wakey wakey
22:59:11.269 [DefaultDispatcher-worker-6] DEBUG xtdb.compactor.Compactor - compacting 'xt/txs' '["l01-rc-b00" "l00-rc-b01"]' -> l01-rc-b01
22:59:11.269 [DefaultDispatcher-worker-5] DEBUG xtdb.compactor.Compactor - compacting 'public/lineitem' '["l01-rc-b00" "l00-rc-b01"]' -> l01-rc-b01
22:59:11.490 [DefaultDispatcher-worker-6] DEBUG xtdb.compactor.Compactor - compacted 'xt/txs' -> 'l01-rc-b01'
22:59:16.608 [DefaultDispatcher-worker-5] DEBUG xtdb.compactor.Compactor - compacted 'public/lineitem' -> 'l01-rc-b01'
22:59:16.676 [DefaultDispatcher-worker-5] TRACE xtdb.compactor.Compactor - wakey wakey
22:59:16.677 [DefaultDispatcher-worker-5] DEBUG xtdb.compactor.Compactor - compacting 'xt/txs' '["l01-rc-b01" "l00-rc-b02"]' -> l01-rc-b02
22:59:16.677 [DefaultDispatcher-worker-9] DEBUG xtdb.compactor.Compactor - compacting 'public/lineitem' '["l01-rc-b01" "l00-rc-b02"]' -> l01-rc-b02
22:59:16.915 [DefaultDispatcher-worker-5] DEBUG xtdb.compactor.Compactor - compacted 'xt/txs' -> 'l01-rc-b02'
22:59:22.523 [DefaultDispatcher-worker-9] DEBUG xtdb.compactor.Compactor - compacted 'public/lineitem' -> 'l01-rc-b02'
22:59:22.699 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacting 'public/partsupp' '["l00-rc-b03"]' -> l01-rc-b03
22:59:22.699 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacting 'public/part' '["l00-rc-b03"]' -> l01-rc-b03
22:59:22.699 [DefaultDispatcher-worker-14] DEBUG xtdb.compactor.Compactor - compacting 'public/lineitem' '["l01-rc-b02" "l00-rc-b03"]' -> l01-rc-b03
22:59:22.699 [DefaultDispatcher-worker-19] DEBUG xtdb.compactor.Compactor - compacting 'xt/txs' '["l01-rc-b02" "l00-rc-b03"]' -> l01-rc-b03
22:59:22.967 [DefaultDispatcher-worker-19] DEBUG xtdb.compactor.Compactor - compacted 'xt/txs' -> 'l01-rc-b03'
22:59:23.015 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacted 'public/part' -> 'l01-rc-b03'
22:59:23.032 [DefaultDispatcher-worker-23] TRACE xtdb.compactor.Compactor - wakey wakey
22:59:23.268 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacted 'public/partsupp' -> 'l01-rc-b03'
22:59:23.626 [main] INFO  xtdb.datasets.tpch - Transacted TPC-H tables...
{"stage":"submit-docs","time-taken-ms":27520,"bench-id":"ed730c73-3f94-43ea-9c28-d31ad5224267","jvm-id":"chuck"}
22:59:23.628 [main] INFO  xtdb.bench - Done stage: :submit-docs
22:59:23.628 [main] INFO  xtdb.bench - Starting stage: :sync
{"stage":"sync","time-taken-ms":0,"bench-id":"ed730c73-3f94-43ea-9c28-d31ad5224267","jvm-id":"chuck"}
22:59:23.628 [main] INFO  xtdb.bench - Done stage: :sync
22:59:23.628 [main] INFO  xtdb.bench - Starting stage: :finish-block
22:59:25.864 [DefaultDispatcher-worker-14] DEBUG xtdb.compactor.Compactor - compacted 'public/lineitem' -> 'l01-rc-b03'
22:59:25.974 [DefaultDispatcher-worker-3] TRACE xtdb.compactor.Compactor - wakey wakey
{"stage":"finish-block","time-taken-ms":2346,"bench-id":"ed730c73-3f94-43ea-9c28-d31ad5224267","jvm-id":"chuck"}
22:59:25.974 [main] INFO  xtdb.bench - Done stage: :finish-block
22:59:25.974 [main] INFO  xtdb.bench - Starting stage: :compact
22:59:25.975 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacting 'xt/txs' '["l01-rc-b03" "l00-rc-b04"]' -> l01-rc-b04
22:59:25.975 [DefaultDispatcher-worker-24] DEBUG xtdb.compactor.Compactor - compacting 'public/nation' '["l00-rc-b04"]' -> l01-rc-b04
22:59:25.975 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacting 'public/partsupp' '["l01-rc-b03" "l00-rc-b04"]' -> l01-rc-b04
22:59:25.975 [DefaultDispatcher-worker-9] TRACE xtdb.compactor.Compactor - compactAll: waiting for idle
22:59:25.975 [DefaultDispatcher-worker-19] TRACE xtdb.compactor.Compactor - wakey wakey
22:59:26.146 [DefaultDispatcher-worker-24] DEBUG xtdb.compactor.Compactor - compacted 'public/nation' -> 'l01-rc-b04'
22:59:26.147 [DefaultDispatcher-worker-24] DEBUG xtdb.compactor.Compactor - compacting 'public/region' '["l00-rc-b04"]' -> l01-rc-b04
22:59:26.149 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacted 'xt/txs' -> 'l01-rc-b04'
22:59:26.149 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacting 'public/supplier' '["l00-rc-b04"]' -> l01-rc-b04
22:59:26.328 [DefaultDispatcher-worker-24] DEBUG xtdb.compactor.Compactor - compacted 'public/region' -> 'l01-rc-b04'
22:59:26.370 [DefaultDispatcher-worker-23] DEBUG xtdb.compactor.Compactor - compacted 'public/supplier' -> 'l01-rc-b04'
22:59:26.507 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacted 'public/partsupp' -> 'l01-rc-b04'
22:59:27.005 [DefaultDispatcher-worker-3] DEBUG xtdb.compactor.Compactor - compacted 'public/partsupp' -> 'l01-rc-b04'
22:59:30.569 [DefaultDispatcher-worker-14] DEBUG xtdb.compactor.Compactor - compacted 'public/lineitem' -> 'l01-rc-b03'
22:59:30.610 [DefaultDispatcher-worker-14] ERROR xtdb.util - Uncaught exception:
java.lang.IllegalStateException: AppendRecord would exceed the maximum allowed metered size of 1MiB, currently 1049854 bytes.
        at s2.types.AppendRecord$AppendRecordBuilder.build(AppendRecord.java:65)
        at chucklehead.xtdb.s2.S2Log$appendMessage$1.invokeSuspend(S2Log.kt:74)

Hey @chuck.cassel just catching up with this thread. Am I right in thinking that your latest observation here is still outstanding/relevant from your perspective? > Could I have a bug that's causing an overly large log entry, or would this be a scenario where a large size would be expected? Potentially yes, we have seen Kafka message size limits present/reveal similar problems previously, although given we test tpch with kafka already I would be surprised that we haven't hit this already 🤔

Yes, still outstanding afaik, but I haven't had time to investigate. I need to put a little effort into getting things working in ECS so I can test more reliably there. Just tried again to reproduce from my laptop but I'm hitting timeout errors before I get to the size limit, but I suspect those are a symptom of the difference in upload speeds between the 10 Mb DSL where I'm currently at for the holiday weekend vs 1Gb at home where I ran the tests last.

This is my diff vs v2.0.0, and I was initially able to trigger it by running /gradlew tpch -PscaleFactor="0.05" -PconfigFile="s2.yaml"

diff --git a/build.gradle.kts b/build.gradle.kts
index dd7a2c029..517e98dd1 100644
--- a/build.gradle.kts
+++ b/build.gradle.kts
@@ -64,9 +64,26 @@ allprojects {
 
     version = System.getenv("XTDB_VERSION") ?: "2.0.0-SNAPSHOT"
 
+    val user = System.getenv("GITHUB_ACTOR")
+    val token = System.getenv("GITHUB_TOKEN")
+    
     repositories {
         mavenCentral()
         maven { url = uri("") }
+        maven {
+            url = uri("")
+            credentials {
+                username = user
+                password = token
+            }
+        }
+        maven {
+            url = uri("")
+            credentials {
+                username = user
+                password = token
+            }
+        }
     }
 
     if (plugins.hasPlugin("java-library")) {
diff --git a/modules/bench/build.gradle.kts b/modules/bench/build.gradle.kts
index b30166cf7..978d668e0 100644
--- a/modules/bench/build.gradle.kts
+++ b/modules/bench/build.gradle.kts
@@ -26,6 +26,7 @@ dependencies {
     api("pro.juxt.clojars-mirrors.hiccup", "hiccup", "2.0.0-alpha2")
 
     api("software.amazon.awssdk", "s3", "2.25.24")
+    api("dev.chucklehead:s2-log:0.0.4")
 }
 
 
diff --git a/s2.yaml b/s2.yaml
new file mode 100644
index 000000000..bf1af1500
--- /dev/null
+++ b/s2.yaml
@@ -0,0 +1,11 @@
+log: !S2
+  token: !Env S2_ACCESS_TOKEN
+  basin: xtdb-log
+  stream: xtdb-bench-express
+  appendTimeout: PT30S
+
+storage: !Remote
+  localDiskCache: ./storage/s3-cache
+  objectStore: !S3
+    bucket: chucklehead-xtdb-bench
+    prefix: xtdb-bench
\ No newline at end of file
diff --git a/src/main/resources/logback-test.xml b/src/main/resources/logback-test.xml
index cc9300d00..bdea98080 100644
--- a/src/main/resources/logback-test.xml
+++ b/src/main/resources/logback-test.xml
@@ -4,8 +4,11 @@
       <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
     </encoder>
   </appender>
-  <root level="WARN">
+  <root level="INFO">
     <appender-ref ref="STDOUT" />
   </root>
   <logger name="xtdb" level="INFO" />
+  <logger name="xtdb.compactor" level="TRACE" />
+  <logger name="xtdb.indexer" level="TRACE" />
+  <logger name="s2.client" level="TRACE" />
 </configuration>

Is there more info I can capture from the cache or node folder or elsewhere that would be helpful if I'm able to reproduce again?