Fluency - High-throughput Fluentd logger for Java

Transcript

1. Fluency Yet another fluent logger Mitsunori Komatsu
2. About me • Mitsunori Komatsu, 
 Software engineer • github:komamitsu
 msgpack-java
 (jackson-dataformat-msgpack),
 fluent-logger-java,
 digdag,
 :
3. Today’s talk • What's Fluency? • Internal design • Performance and profiling • Future improvements
4. Fluentd
5. What’s Fluency? • Yet another fluent-logger-java
 (https://github.com/komamitsu/fluency) • 3x 4x faster than fluent-logger using PackedForward format • Easy to extend • Many features
 (Async flush, HB, Failover, Ack response) • Used in LINE, Treasure Data, kafka-fluentd-consumer
6. Internal design • Asynchronous flushing • Buffering PackedForward format data
7. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
8. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
9. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
10. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
11. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
12. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
13. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
14. Async flushing Application Fluency Buffer Fluentd Flusher emit(event:A) append(event:A) emit(event:B) append(event:B) store events as MessagePack flush send(event:[A, B]) emit(event:C) append(event:C) flush invoked repeatedly PackedForward format close close force flush emit(event:D) append(event:D) send(event:[C,D]) event:C isn’t ready for flush event:A,B are ready for flush terminate thread
15. Buffering events tag: aaa, time: 100, {name: a_0} Buffer pool retention buffers flushable buffers Fluentd emit event acquire buffer
16. Buffering events tag: bbb, time: 101, {name: b_0} Buffer pool time: 100, {name: a_0} retention buffers flushable buffers tag: aaa Fluentd emit event acquire buffer
17. Buffering events tag: ccc, time: 102, {name: c_0} Buffer pool time: 100, {name: a_0} time: 101, {name: b_0} retention buffers flushable buffers tag: aaa tag: bbb Fluentd emit event acquire buffer
18. Buffering events tag: aaa, time: 110, {name: a_1} Buffer pool time: 100, {name: a_0} time: 101, {name: b_0} time: 102, {name: c_0} retention buffers flushable buffers tag: aaa tag: bbb tag: ccc Fluentd emit event
19. Buffering events tag: aaa, time: 120, {name: a_2} Buffer pool time: 100, {name: a_0} time: 110, {name: a_1} time: 101, {name: b_0} time: 102, {name: c_0} retention buffers flushable buffers tag: aaa tag: bbb tag: ccc Fluentd emit event expand buffer
20. Buffering events tag: bbb, time: 111, {name: b_1} : : Buffer pool time: 100, {name: a_0} time: 110, {name: a_1} time: 120, {name: a_2} time: 101, {name: b_0} time: 102, {name: c_0} retention buffers flushable buffers tag: aaa tag: bbb tag: ccc Fluentd emit event
21. Buffering events tag: aaa, time: 200, {name: a_0} Buffer pool time: 100, {name: a_0} time: 110, {name: a_1} time: 120, {name: a_2} time: 130, {name: a_3} time: 101, {name: b_0} time: 111, {name: b_1} time: 121, {name: b_2} time: 131, {name: b_3} time: 102, {name: c_0} time: 112, {name: c_1} retention buffers flushable buffers tag: aaa tag: bbb tag: ccc Fluentd emit event move buffers (zero copy)
22. tag: aaa Buffering events tag: ccc, time: 122, {name: c_2} Buffer pool time: 200, {name: a_0} time: 102, {name: c_0} time: 112, {name: c_1} retention buffers flushable buffers tag: aaa tag: ccc time: 100, {name: a_0} time: 110, {name: a_1} time: 120, {name: a_2} time: 130, {name: a_3} Fluentd tag: bbb time: 101, {name: b_0} time: 111, {name: b_1} time: 121, {name: b_2} time: 131, {name: b_3} emit event expand buffer send buffer return buffer (after sending) PackedForword format
23. Buffering events tag: bbb, time: 201, {name: b_0} Buffer pool time: 200, {name: a_0} time: 102, {name: c_0} time: 112, {name: c_1} retention buffers flushable buffers tag: aaa tag: ccc Fluentd tag: bbb time: 101, {name: b_0} time: 111, {name: b_1} time: 121, {name: b_2} time: 131, {name: b_3} time: 122, {name: c_2} emit event send buffer return buffer (after sending) acquire buffer PackedForword format
24. Buffering events tag: aaa, time: 210, {name: a_1} Buffer pool time: 200, {name: a_0} time: 102, {name: c_0} time: 112, {name: c_1} retention buffers flushable buffers tag: aaa tag: ccc Fluentd time: 122, {name: c_2} time: 201, {name: b_0} tag: bbb emit event
25. 4x faster than
 fluent-logger-java fluency / fluent-logger-java: m3.large fluentd: m3.large See details: https://gist.github.com/komamitsu/c1e4045fe2ddb108cfbf12d5f014b683 But the actual bottleneck of this benchmark might be Fluentd…
26. Java profiling (1/2) fluency fluent-logger-java fluency uses off heap for buffer pool Due to synchronization
27. Java profiling (2/2) fluency fluent-logger-java GC Pause: 33ms/s GC Pause: 7ms/s
28. Finding a bottleneck fluency emit (MessagePack serialization & appending to buffer) accounts for most of the duration String.getBytes in MessagePack serialization takes total 18% ObjectMapper.writeValue itself takes 40%
29. Finding a bottleneck fluency MessagePackGenerator. writeStartArray takes 10% java.nio.channels.SocketCh annel.write and java.nio.ByteBuffer.allocate Direct are both 0-1%
30. Finding a bottleneck fluent-logger-java Sending events via socket accounts for most of the duration
31. Future improvements: removing ObjectMapper ObjectMapper can be removed to improve performance? Hmm. But Fluency accepts Jackson Modules…
32. Future improvements: reducing use of ObjectMapper ObjectMapper is needed only for serialisation of data not array
33. Thanks!