This message was deleted.
# general
s
This message was deleted.
y
Do you have metrics setup on bookies? My first guess is on bookie side. In the beginning, it is fast because the messages are still in cache.
👍 1
m
Yes, we have metrics on bookies, have you one in mind ?
a
@Hang Chen You have a talk on this no?
l
I gave a talk last year that gives some advice. Slides: https://www.apachecon.com/acna2022/slides/03_Hotari_Lari_Performance_tuning_Pulsar.pdf Recording:

https://www.youtube.com/watch?v=WkdfILAx-4c▾

m
Thanks, I will take time to watch it
l
Another talk by Hang Chen:

https://youtu.be/8_4bVctj2_E?feature=shared▾

h
From the logs, the p99 read latency is two high, and you’d better check the bookie dashboard
k
We can see heavy latency on reads. We are running on 8 threads VM, with default BK configuration so maybe we are configuring too much threads for the VM resources but the CPU load/RAM usages are not heavy.
Copy code
# 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 16
45K context switch per second is legit?
y
high cs is normal as long as sys is not over single digit.
k
I have a lot of auth/disconnections from brokers such as
Copy code
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.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]
^C
is that normal behavior ?
also, it looks BK doesn't check for epoll availability
I think I have a lot of epoll.wait ongoing concurrently
We have good writes rates, only reads are very low.
Copy code
yo-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.1107050174E10
l
We 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 .
k
Indeed. Ok thanks, checking that.
I'll bump BK from 4.16.3 to 4.16.6.
@Lari Hotari our use cases is ~15000topics having ~1000msg/s, on we do reads on these from custom messageId. Any RocksDB tuning advices?
l
What I would do is first trying to understand where the bottleneck is then experiment with tuning that the bottleneck can be eliminated. For RocksDB, you need to give enough RAM for it so that lookups happen in memory and don't cause disk IO. What's your current bookkeeper config?
dbStorage_rocksDB_blockCacheSize
is the name of the config parameter
k
We use the default one.
We tried using BK on
-Xms8192m -Xmx8192m -XX:MaxDirectMemorySize=8076m
And
-Xms24g -Xmx24g -XX:MaxDirectMemorySize=24g
, no big deal.
(With a 16GB RAM, and a 64GB RAM)
BTW, we put too much Xmx, MaxdirectMemorySize for the 16GB 😮. Maybe it's the root cause. Fixing..
l
btw.
dbStorage_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.
k
Ack
l
y
do you have worker node iostat?
l
our 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.
k
vdb is used as storage for BK:
Copy code
yo-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          0
In fact isn't really 1000msg/s. We have thousands of applications that push their logs (one topic per app).
Then depending on requests we need to provide logs for an application.
We use the admin api to get the messageid for a given timestamp and we start a reader for it.
l
what type of disks do you have? local or over network? SSD or HDD?
k
Each BK has its own SSD directly assign through qemu.
Each BK has a 4TB SSD
l
local SSD, so no network storage system (SAN)?
k
Copy code
yo-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/s
Yes local SSD.
👍 1
We have 5 proxies/ 5brokers, and 34 BK nodes as mentioned.
Shared in 3 DC with regionaware
l
it feels that there's sufficient amount of HW resources for the use case. 🙂 it will definitely help to find the metrics which pinpoint the problem. My current assumption is that the Rocksdb entry location lookups could be a bottleneck. The metrics could reveal that. https://github.com/apache/bookkeeper/commit/19fd8f74 is already in 4.16.0 so there should be a need to bump BK version to get the metrics if you are already on 4.16.x. One way to experiment with dbStorage_rocksDB_blockCacheSize tuning would be to set it to the 2GB in bytes which is
2147483648
and see if the metrics are any different after that.
k
Ok thanks, I'll keep you posted!
We applied the 2GB to blockCacheSize, but maybe we also need to add more RAM/cpu (on vm, so jvm) and threads (read, write, journal etc. in bk conf). And here is a representative metrics of lookup_entry_location for one BK node:
Copy code
bookie_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.0882591E7
Machines with 8threads (vCPU), AMD EPYC 7713P, 15GB RAMavailable : 4GB xmx/xms, 4GB maxdirectmemorysize and 2GB blockcachesize
Copy code
bookie_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 size
l
@kannarfr what are E, Qw and Qa values? The reason I'm asking is that sticky reads aren't enabled in the bookkeeper client unless ensemble size equals write quorum size. However, you should also be able to see that from metrics when cache misses are high in bookkeeper. without sticky reads, the read ahead cache won't be efficient in bk.
k
E=5, Qw3, Qa=2
Ok, bumping conf.. 🙂
got burned by that before... 🙂 that's why I made https://github.com/apache/pulsar/pull/18003
k
Clear, thanks a lot!
👍 1
l
When you have a lot of consumers, there are some gotchas in tuning the broker entry cache which makes a big difference. In your use case, I guess you don't have a lot of consumers that could benefit from a well tuned broker entry cache?
k
Talking about
dispatcherMaxReadBatchSize
?
l
no,
managedLedgerCache*
and
managedLedger*ForCaching
configs
k
I think it can be worth it to increase them. We can have several consumers created on the same topic when we looking for errors in logs, like read part of topic, search reread with filters etc.
Nice tip 🙂.
l
tuning those help tailing read and catchup read scenarios with a large amount of consumers (100s / 1000s)
k
Clear, ty
l
Which Pulsar version are you using?
k
3.1.1
👍 1
Is it safe when cluster is already running to restart bk with the
entryLogPerLedgerEnabled=true
? (from false to true)
(how many open files can we tolerate for it?)
l
I don't remember touching that config. A search in the source code reveals that there's a need to set
useTransactionalCompaction=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?
k
FYI, since ensemble=Qw, reads rates have increased x30. We will soon increase broker readbatchsize (on bk reads) from 100 to 500 and see if it increases the rates too (it won't be that big but let's see).
Thanks a lot for your diag & advices Lari!
thankyou 1
a
@kannarfr Help you fellow users and include this tip in the docs . Very easy to do PR for pulsar-site repo
l
a
Hmm @kannarfr where would you put if, for your last-week self for you to notice it?
k
Maybe a bullet point about stickyreads here https://bookkeeper.apache.org/docs/admin/bookies#performance?
💯 1
a
@kannarfr Would you like to contribute the fix to this section?
k
https://github.com/apache/bookkeeper/pull/4131, as it's public doc, maybe you have some hints about phrasing. Do not hesitate to tell me.