Slackbot
10/25/2023, 9:21 AMYu Wei Sung
10/25/2023, 12:33 PMmiton18
10/25/2023, 12:35 PMAsaf Mesika
10/25/2023, 1:18 PMLari Hotari
10/25/2023, 2:27 PMmiton18
10/25/2023, 3:02 PMHang Chen
10/26/2023, 9:30 AMkannarfr
10/29/2023, 3:28 PMkannarfr
10/29/2023, 3:36 PM# TYPE jvm_threads_current gauge
jvm_threads_current{} 106.0
# TYPE jvm_threads_daemon gauge
jvm_threads_daemon{} 12.0
# TYPE jvm_threads_peak gauge
jvm_threads_peak{} 108.0
# TYPE jvm_threads_started counter
jvm_threads_started_total{} 183.0
# TYPE jvm_threads_deadlocked gauge
jvm_threads_deadlocked{} 0.0
# TYPE jvm_threads_deadlocked_monitor gauge
jvm_threads_deadlocked_monitor{} 0.0
# TYPE jvm_threads_state gauge
jvm_threads_state{state="NEW"} 0.0
jvm_threads_state{state="TERMINATED"} 0.0
jvm_threads_state{state="RUNNABLE"} 46.0
jvm_threads_state{state="BLOCKED"} 0.0
jvm_threads_state{state="WAITING"} 47.0
jvm_threads_state{state="TIMED_WAITING"} 13.0
jvm_threads_state{state="UNKNOWN"} 0.0
# TYPE replication_bookkeeper_client_BookKeeperClientWorker_threads gauge
replication_bookkeeper_client_BookKeeperClientWorker_threads 8
# TYPE bookkeeper_server_BookieHighPriorityThread_threads gauge
bookkeeper_server_BookieHighPriorityThread_threads 8
# TYPE bookkeeper_server_BookieReadThreadPool_threads gauge
bookkeeper_server_BookieReadThreadPool_threads 16kannarfr
10/29/2023, 4:11 PMYu Wei Sung
10/30/2023, 12:49 PMkannarfr
11/03/2023, 12:06 AMNov 03 00:06:19 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:19,176+0000 [bookie-io-8-61] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side
Nov 03 00:06:19 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:19,176+0000 [bookie-io-8-61] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channel connected [id: 0x72e0b545, L:/192.168.4.1:3181 - R:/192.168.4.14:53946]
Nov 03 00:06:19 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:19,251+0000 [bookie-io-8-57] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channels disconnected: [id: 0xd092da68, L:/192.168.4.1:3181 ! R:/192.168.4.2:34750]
Nov 03 00:06:19 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:19,722+0000 [bookie-io-8-62] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side
Nov 03 00:06:19 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:19,722+0000 [bookie-io-8-62] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channel connected [id: 0x2228a62c, L:/192.168.4.1:3181 - R:/192.168.4.25:42920]
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,102+0000 [bookie-io-8-63] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,103+0000 [bookie-io-8-63] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channel connected [id: 0x55aae591, L:/192.168.4.1:3181 - R:/192.168.4.3:39146]
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,566+0000 [bookie-io-8-64] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,566+0000 [bookie-io-8-64] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channel connected [id: 0x9602b7e2, L:/192.168.4.1:3181 - R:/192.168.4.22:34308]
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,864+0000 [bookie-io-8-65] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side
Nov 03 00:06:20 clevercloud-bookkeeper-c3-n1 pulsar[713846]: 2023-11-03T00:06:20,864+0000 [bookie-io-8-65] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channel connected [id: 0x49c37bce, L:/192.168.4.1:3181 - R:/192.168.4.20:44160]
^Ckannarfr
11/03/2023, 12:07 AMkannarfr
11/03/2023, 12:07 AMkannarfr
11/03/2023, 12:09 AMkannarfr
11/03/2023, 2:50 PMkannarfr
11/03/2023, 3:44 PMyo-bookkeeper-c3-n31 ~ # curl <http://localhost:9102/metrics> -s | grep SCHEDULING
# TYPE bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY summary
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.5"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.75"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.95"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.99"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.999"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="0.9999"} NaN
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="false",quantile="1.0"} -Infinity
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY_count{success="false"} 0
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY_sum{success="false"} 0.0
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.5"} 224.811
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.75"} 590.511
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.95"} 9647.003
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.99"} 14450.689
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.999"} 15079.686
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="0.9999"} 15205.121
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY{success="true",quantile="1.0"} 15322.502
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY_count{success="true"} 39986424
bookkeeper_server_READ_ENTRY_SCHEDULING_DELAY_sum{success="true"} 4.1107050174E10Lari Hotari
11/03/2023, 3:51 PMWe have good writes rates, only reads are very low.
Interesting. I guess you haven't found the bottleneck yet? Could you check the RocksDB entry location index lookups metrics? They were added in this PR: https://github.com/apache/bookkeeper/pull/3444 .
kannarfr
11/03/2023, 3:52 PMkannarfr
11/03/2023, 3:55 PMkannarfr
11/03/2023, 3:59 PMLari Hotari
11/03/2023, 4:06 PMLari Hotari
11/03/2023, 4:10 PMdbStorage_rocksDB_blockCacheSize is the name of the config parameterkannarfr
11/03/2023, 4:10 PMkannarfr
11/03/2023, 4:11 PM-Xms8192m -Xmx8192m -XX:MaxDirectMemorySize=8076mkannarfr
11/03/2023, 4:11 PM-Xms24g -Xmx24g -XX:MaxDirectMemorySize=24g , no big deal.kannarfr
11/03/2023, 4:13 PMkannarfr
11/03/2023, 4:14 PMLari Hotari
11/03/2023, 4:17 PMdbStorage_rocksDB_blockCacheSize value defaults to 10% of configured max direct memory and it gets allocated outside of JVM's direct memory area (which is a bit misleading). I'd recommend setting it to an explicit value. However tuning values without knowing the bottleneck could be a bad thing to do.kannarfr
11/03/2023, 4:17 PMLari Hotari
11/03/2023, 4:18 PMYu Wei Sung
11/03/2023, 4:30 PMLari Hotari
11/03/2023, 4:39 PMour use cases is ~15000topics having ~1000msg/s, on we do reads on these from custom messageId. Any RocksDB tuning advices?@kannarfr when you say "we do reads on these from custom messageId", do you mean that you start readers from a specific messageId as the earliest message? what is the approximate rate of this type of workload? how many messages are typically read using the reader before it is closed? Just trying to understand the usecase and the access pattern that it has.
kannarfr
11/03/2023, 4:52 PMyo-bookkeeper-c3-n1 ~ # iostat
Linux 6.1.19+ (yo-bookkeeper-c3-n1) 03/11/23 _x86_64_ (50 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
3.46 0.00 1.95 0.47 0.02 94.10
Device tps kB_read/s kB_wrtn/s kB_dscd/s kB_read kB_wrtn kB_dscd
vda 34.13 45.85 181.00 0.00 4345754 17154144 0
vdb 1760.44 1178.39 19142.06 0.00 111684161 1814225152 0kannarfr
11/03/2023, 4:52 PMkannarfr
11/03/2023, 4:52 PMkannarfr
11/03/2023, 4:53 PMLari Hotari
11/03/2023, 4:53 PMkannarfr
11/03/2023, 4:54 PMkannarfr
11/03/2023, 4:54 PMLari Hotari
11/03/2023, 4:55 PMkannarfr
11/03/2023, 4:55 PMyo-bookkeeper-c3-n1 /data # dd if=/dev/zero of=test bs=20G count=1 oflag=dsync
0+1 records in
0+1 records out
2147479552 bytes (2.1 GB, 2.0 GiB) copied, 2.78952 s, 770 MB/skannarfr
11/03/2023, 4:55 PMkannarfr
11/03/2023, 4:58 PMkannarfr
11/03/2023, 4:58 PMLari Hotari
11/03/2023, 5:04 PM2147483648 and see if the metrics are any different after that.kannarfr
11/03/2023, 5:24 PMkannarfr
11/03/2023, 8:30 PMbookie_lookup_entry_location{success="false",quantile="0.5", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="0.75", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="0.95", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="0.99", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="0.999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="0.9999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location{success="false",quantile="1.0", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.535
bookie_lookup_entry_location_count{success="false", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 202
bookie_lookup_entry_location_sum{success="false", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 2842.0
bookie_lookup_entry_location{success="true",quantile="0.5", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 10.578
bookie_lookup_entry_location{success="true",quantile="0.75", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 12.398
bookie_lookup_entry_location{success="true",quantile="0.95", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 14.001
bookie_lookup_entry_location{success="true",quantile="0.99", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 15.024
bookie_lookup_entry_location{success="true",quantile="0.999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 17.495
bookie_lookup_entry_location{success="true",quantile="0.9999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 22.982
bookie_lookup_entry_location{success="true",quantile="1.0", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 25.474
bookie_lookup_entry_location_count{success="true", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 991563
bookie_lookup_entry_location_sum{success="true", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 1.0882591E7kannarfr
11/03/2023, 8:32 PMkannarfr
11/03/2023, 8:33 PMbookie_lookup_entry_location{success="false",quantile="0.5", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="0.75", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="0.95", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="0.99", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="0.999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="0.9999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} NaN
bookie_lookup_entry_location{success="false",quantile="1.0", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} -Infinity
bookie_lookup_entry_location_count{success="false", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 45
bookie_lookup_entry_location_sum{success="false", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 626.0
bookie_lookup_entry_location{success="true",quantile="0.5", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 6.934
bookie_lookup_entry_location{success="true",quantile="0.75", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 9.568
bookie_lookup_entry_location{success="true",quantile="0.95", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 10.465
bookie_lookup_entry_location{success="true",quantile="0.99", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 11.192
bookie_lookup_entry_location{success="true",quantile="0.999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 12.949
bookie_lookup_entry_location{success="true",quantile="0.9999", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 12.949
bookie_lookup_entry_location{success="true",quantile="1.0", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 15.896
bookie_lookup_entry_location_count{success="true", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 634044
bookie_lookup_entry_location_sum{success="true", indexDir="/data/bookkeeper/ledgers/current",ledgerDir="/data/bookkeeper/ledgers/current"} 6079337.0
machines with 50 threads (vcpu), 64GB RAM available: 24GB xmx/xms, 24GB direct memory and 2GB blockcache sizeLari Hotari
11/04/2023, 11:58 AMkannarfr
11/04/2023, 11:59 AMkannarfr
11/04/2023, 11:59 AMLari Hotari
11/04/2023, 12:00 PMLari Hotari
11/04/2023, 12:00 PMkannarfr
11/04/2023, 12:01 PMLari Hotari
11/04/2023, 12:05 PMkannarfr
11/04/2023, 12:06 PMdispatcherMaxReadBatchSize ?Lari Hotari
11/04/2023, 12:08 PMmanagedLedgerCache* and managedLedger*ForCaching configskannarfr
11/04/2023, 12:09 PMkannarfr
11/04/2023, 12:09 PMLari Hotari
11/04/2023, 12:10 PMkannarfr
11/04/2023, 12:10 PMLari Hotari
11/04/2023, 12:14 PMkannarfr
11/04/2023, 12:15 PMkannarfr
11/06/2023, 3:07 PMentryLogPerLedgerEnabled=true ? (from false to true)kannarfr
11/06/2023, 3:09 PMLari Hotari
11/07/2023, 8:11 AMuseTransactionalCompaction=true when you set entryLogPerLedgerEnabled=true .
https://github.com/apache/bookkeeper/blob/branch-4.16/bookkeeper-server/src/main/java/org/apache/bookkeeper/conf/ServerConfiguration.java#L31[…]3179
You need a good representative test environment to validate such configurations since there might not be many others running Pulsar with such config. The feature does look interesting based on the issue description. However, it might just be a distraction and cause more variation when you are looking into finding the bottleneck and resolving it in your particular scenario?kannarfr
11/08/2023, 11:45 PMkannarfr
11/08/2023, 11:45 PMAsaf Mesika
11/09/2023, 9:28 AMLari Hotari
11/09/2023, 9:49 AMAsaf Mesika
11/09/2023, 11:21 AMkannarfr
11/09/2023, 3:04 PMAsaf Mesika
11/13/2023, 10:56 AMkannarfr
11/15/2023, 2:31 PM