SF Big Analytics July 2017 - Pushing the Limits of Kafka

This was a talk given at SF Big Analytics in July 2017. This talk details a subset of challenges Heroku has encountered in operating Apache Kafka as a service in production for the last several years. For each challenge and incident, we talk about the observed behaviors, followed by deep dive into Kafka internals, and then key insights, takeaways, and practical fixes.

Transcript

1. Beyond 50,000 Partitions How Heroku Operates and Pushes the Limits of Kafka at Scale Jeff Chao SF Big Analytics, July 2017
2. Core concepts & fundamentals of Kafka
3. Distributed messaging system Apache Kafka is a
4. Five fundamental components And consists of
5. Brokers Topics and Partitions Producers and Consumers
6. Broker Topic Partitions p0 p1 p2
7. p0 m 1 m 2 . . . m n
8. m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n Topic: user_events Topic: system_events Topic: alerts Topic: control_messages
9. m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n m 1 m 2 . . . m n ( low throughput ) ( high throughput ) ( oldest ) ( newest )
10. Broker Topic Partitions p0 p1 p2
11. Topic : user_events p0 p1 p2 Producers writes to Consumers reads from
12. Topic : user_events p0 p1 p2 Producers { “user_id”: 1, “message”: “foo” }
13. Topic : user_events p0 p1 p2 Consumers Consumer 1 Consumer 2 p2, offset: 25 p0, offset: 10 p1, offset: 5
14. Process at their own speeds Allows consumers to not only
15. Recover their progress after a failure occurs Consumers can also individually
16. Many other moving pieces Operating Kafka as scale
17. Replication How does Kafka achieve HA?
18. Quota management and security How do we prevent abuse from misbehaving users?
19. OS, JVM, Kafka Tuning Heap, off-heap, I/O threads, network request threads, controllers, leaders, logs, log segments
20. Managing Zookeeper A whole other talk
21. Underlying physical or virtual infrastructure
22. Monitoring & Metrics VPC, SSL, JMX, RMI, Jolokia Networking Disk Automatic volume growth, corruption & replacement Logging
23. Version upgrades How do you upgrade to new versions? What do you do when faced with breaking changes?
24. Maintenance How do you detect underlying server or disk corruption and automate a replacement strategy?
25. PRODUCERS CONSUMERS BROKER TOPIC PARTITION Apache Kafka Fully-Managed
26. Hundreds of clusters Thousands of partitions per broker
27. 150 MB/s sustained Individual clusters — produce and consume traffic, < 5ms latency
28. Data centers around the world Operate clusters in
29. Striped across availability zones All brokers and Zookeeper nodes
30. Rack-aware partition placement strategy Across availability zones
31. Interested in pushing the limits of Kafka Get ahead of challenges that might come up
32. Our users wouldn’t have to face them In production
33. Built internal tooling and infrastructure
34. Variety of challenges operating Kafka at scale
35. 1 2 3
37. Network threads getting NPEs Observed behavior 3 Observed behavior 1 Brokers were crashing and being restarted Users were exceeding their produce quotas Observed behavior 2
38. Quotas Major key alert
39. Leverage Kafka’s quota implementation At Heroku, we
40. Traffic Shaping over Traffic Policing Kafka favors
41. Avoid dropping messages Motivation
42. Enforced on either Producers or Consumers Can throttle on ingest or consumption
43. ( quota = 5 MB/s ) Producers { “id”: 1, “msg”: “...” } { “id”: 2, “msg”: “...” } { “id”: 5, “msg”: “...” } { “id”: 4, “msg”: “...” } { “id”: 2, “msg”: “...” } { “id”: 3, “msg”: “...” } { “id”: 3, “msg”: “...” } { “id”: 1, “msg”: “...” } { “id”: 2, “msg”: “...” } { “id”: 1, “msg”: “...” } ( write throughput = 10 MB/s ) ( throughput = 10 MB/s ) { “id”: 1, “msg”: “...” } { “id”: 2, “msg”: “...” } { “id”: 5, “msg”: “...” } { “id”: 4, “msg”: “...” } { “id”: 2, “msg”: “...” } User’s Perspective { “id”: 3, “msg”: “...” } { “id”: 3, “msg”: “...” } { “id”: 1, “msg”: “...” } { “id”: 2, “msg”: “...” } { “id”: 1, “msg”: “...” } ( delayed )
44. Requires enough space on the broker For holding all of these queued requests
45. Stores only what’s necessary Kafka does a great job in making sure that it
46. There was a bug Turns out...
47. pri=ERROR t=kafka-network-thread-0-SSL-0 at=Processor Processor got uncaught exception. java.lang.OutOfMemoryError: Java heap space
48. Network threads getting NPEs Observed behavior 3 Observed behavior 1 Brokers were crashing and being restarted Users were exceeding their produce quotas Observed behavior 2
49. Dealing with heap-based OOM problems First thing
51. Produce Request Lifecycle Writing messages to Kafka
52. KafkaApis#handleProducerRequest replicaManager.appendRecords( produceRequest.timeout.toLong, produceRequest.acks, internalTopicsAllowed, authorizedRequestInfo, sendResponseCallback) produceRequest.clearPartitionRecords()
53. ReplicaManager#appendRecords // true if required acks = all, data to append, or partial success if (delayedProduceRequestRequired(requiredAcks, ...)) { ... // calls responseCallback eventually delayedProducePurgatory.tryCompleteElseWatch(...) } else { ... responseCallback(produceResponseStatus) }
54. ClientQuotaManager#recordAndMaybeThrottle try { // trigger the callback immediately if quota is not violated callback(0) } catch { case _: QuotaViolationException => val throttleTimeMs = ... // Compute the delay clientSensors.throttleTimeSensor.record(throttleTimeMs) delayQueue.add(new ThrottledResponse(...)) }
55. KafkaApis#handleProducerRequest replicaManager.appendRecords( produceRequest.timeout.toLong, produceRequest.acks, internalTopicsAllowed, authorizedRequestInfo, sendResponseCallback) produceRequest.clearPartitionRecords()
56. Messages already extracted from the request After this point
57. Unnecessarily taking up memory If held
58. Wasn’t entirely true Turns out...
59. Not actually clearing out all references Heap-based OOM
60. Filed a JIRA
61. Blocked the release
62. Submitted a patch upstream
63. Landed in Kafka 0.10.2
64. 1 2 Heap-Based OOM
65. Some brokers booted, but suddenly fail again Observed behavior 3 Observed behavior 1 Brokers restarted, not able to boot up Cascading failure of brokers Observed behavior 2
66. Shouldn’t expect availability 100% of the time Services can fail
67. Services hosted on AWS
68. Failing regularly and unable to restart Still odd that brokers were
69. What is Kafka’s HA Model? What happens when a broker goes down? What happens when a broker comes up?
70. p0-lead user_events p2-lead p1-lead p0 writes reads ( replicated ) p1 p2 [ p0, p1, p2 ] p1 p2 p0 p2 p1 p0 other broker other broker
71. Balanced leadership among brokers In general, Kafka tries to
72. Lead for only a subset of all partitions Brokers are generally
73. Example - load distribution 5 brokers, 1 topic, 50 partitions
74. Example - load distribution A broker will be leader for 10 partitions (on average, 50 partitions / 5 brokers)
75. Example - load distribution Process read and write requests For 10 out of 50 partitions for that given topic
76. Example - fault tolerance Replication factor = 3 is set per topic 2 additional copies of each partition will live on other brokers in the cluster
77. Replication is pull-based Followers run ReplicaFetcherThreads and continuously pull messages from their leaders
78. Each leader maintains In-Sync Replicas Leaders manage a set of In-Sync Replicas (ISR) that represent all followers that are caught up
79. Leaders will evict lagging replicas If followers get stuck or lagged, their leader will remove them from the ISR
80. Important for when a broker fails over
81. Only followers in the ISR may be elected On failover
82. What is Kafka’s HA Model? What happens when a broker goes down? What happens when a broker comes up?
83. Controller 1 per cluster, KafkaController.scala Manages states of partitions and replicas Using state machines
84. Which brokers are leader for which partitions Important for administrative tasks such as determining
85. PartitionStateMachine.scala NonExistentPartition -> NewPartition NewPartition -> OnlinePartition OnlinePartition, OfflinePartition -> OnlinePartition NewPartition, OnlinePartition, OfflinePartition -> OfflinePartition OfflinePartition -> NonExistentPartition
86. Many partitions will go Offline at once When a broker goes down generally
87. Lead for a subset of all partitions Brokers are generally
88. Two cases for brokers failing Clean Shutdown Unclean Shutdown
89. KafkaServer#shutdown controlledShutdown() brokerState.newState(BrokerShuttingDown) if (socketServer != null) socketServer.shutdown() if (requestHandlerPool != null) requestHandlerPool.shutdown() // ... Shutdown other managers and listeners ... info(“shut down completed”) Clean Shutdown
90. Brokers won’t be able to notify the controller Unclean shutdown
91. KafkaHealthcheck#register // Creates Zookeeper ephemeral znode on broker start zkUtils.registerBrokerInZk(...) Unclean Shutdown
92. Broker dies = Zookeeper session dies
93. Ephemeral znode goes away When a Zookeeper session dies the
94. PartitionStateMachine#handleStateChange try { targetState match { ... case OfflinePartition => // pre: partition should be in New or Online state assertValidPreviousStates(...) partitionState.put(topicAndPartition, OfflinePartition) // post: partition has no alive leader ... } } Unclean Shutdown
95. KafkaController#onBrokerFailure val deadBrokersThatWereShuttingDown = ... val partitionsWithoutLeader = ... partitionStateMachine.handleStateChanges(partitionsWithoutLeader, ...) partitionStateMachine.triggerOnlinePartitionStateChange() if (partitionsWithoutLeader.isEmpty) { sendUpdateMetadataRequest(context.liveOrShuttingDownBrokerIds.toSeq) } Unclean Shutdown
96. What is Kafka’s HA Model? What happens when a broker goes down? What happens when a broker comes up?
97. KafkaServer#startup (abridged) logManager.startup() metadataCache = new MetadataCache(config.brokerId) credentialProvider = new CredentialProvider(config.saslEnabledMechanisms) socketServer.startup() replicaManager.startup() kafkaController.startup() groupCoordinator.startup() apis = new KafkaApis(...) requestHandlerPool = new KafkaRequestHandlerPool(...) dynamicConfigManager.startup() Broker Starting
98. KafkaServer#startup (cont.) /* tell everyone we are alive */ val listeners = config.advertisedListeners.map { endpoint => ... } kafkaHealthcheck.startup() checkpointBrokerId(config.brokerId) registerStats() brokerState.newState(RunningAsBroker) startupComplete.set(true) isStartingUp.set(false) AppInfoParser.registerAppInfo(jmxPrefix, config.brokerId.toString) info(“started”) Broker Starting
99. A lot of work for failovers and restarts Major key takeaway
100. Work = f(number of partitions on a broker)
101. More partitions = more work
102. More time required for brokers to recover More work =
103. This could take awhile Thousands of partitions per broker
104. Automation did not consider this Unfortunately at the time...
105. Automation would restart brokers just fine Recovery could take longer than expected Automation would time out the broker
106. Automation was a little too aggressive Wow. Much restarts. Such remediation.
107. The Fix Introduce recovery state
108. The Fix Allow brokers enough time to recover
109. The Fix Monitor and alert on usually long recovery
110. The Fix On long recovery, page a human Don’t attempt automatic remediation
111. 1 2 3 Heap-Based OOM Automation & Remediation
112. Under-replicated partitions, request timeouts Observed behavior 3 Observed behavior 1 Brokers crashing at various stages on boot Long period of stability, sudden failure Observed behavior 2
113. Automation was not interfering What do we say about interfering with recovery? “Not today!”
114. Brokers load all of their partitions Recall that brokers go into recovery on boot up
115. What does it mean to load a partition?
116. Log Anatomy of a Partition (a Log) m 1 m 2 m 3 m 4 m 5 log segment 1 m 6 m 7 m 8 m 9 m 10 log segment 2 m 11 m 12 m 13 m 14 m 15 log segment 3 00:00 - 03:00 or 0 GB - 1 GB 03:00 - 06:00 or 1 GB - 2 GB 06:00 - 09:00 or 2 GB - 3 GB
117. Many files on disk In aggregate
118. Thousands of partitions per broker
119. That’s a lot of file descriptors!
120. Read and completely load all log segments Recall that on boot up, brokers need to
121. Use FDs only for active segments Otherwise during normal operation, Kafka tries to
122. Temporarily hold onto FDs for old segments While logs are being rolled
123. Looking at the service’s operational logs
124. pri=ERROR t=kafka-socket-acceptor-ListenerName at=Acceptor Error while accepting connection java.io.IOException: Too many open files in system
125. $ cat /proc/sys/fs/file-nr 100_000 0 100_000 $ echo ‘Need more file descriptors!’
126. fs.file-max={system_file_descriptor_limit} // sysctl.conf {system_user} - nofile {file_descriptor_limit} // limits.conf $ echo ‘Increase file descriptors and keep a buffer for the system.’ The Fix
127. Rule of Thumb ~1.5 file descriptors per log segment Log segments consists of 3 actual files on disk: .log, .index, and .timeindex However, in our testing, we found on average, ~1.5 FDs per log segment Kafka tries to hold FDs only for active segments
128. Rule of Thumb Inputs (per broker)
129. Rule of Thumb Inputs (per broker) partitions_replicas = (topics * partitions * replication_factor) / brokers
130. Rule of Thumb Inputs (per broker) partitions_replicas = (topics * partitions * replication_factor) / brokers segments_per_partition_replicas = retention_time / log.roll.hours
131. Rule of Thumb Inputs (per broker) partitions_replicas = (topics * partitions * replication_factor) / brokers segments_per_partition_replicas = retention_time / log.roll.hours fd_buffer = tunable (e.g., 1, 1.5, 2) fd = partitions_replicas * segments_per_partition_replicas * fd_buffer
132. Can the broker boot now? Not yet.
133. Under-replicated partitions, request timeouts Observed behavior 3 Observed behavior 1 Brokers crashing at various stages on boot Long period of stability, sudden failure Observed behavior 2
134. 3 different errors In the broker’s service logs
135. pri=FATAL t=ReplicaFetcherThread-0-6 at=ReplicaFetcherThread [ReplicaFetcherThread-0-6], Disk error while replicating data for salmon-84320.messages4-24 kafka.common.KafkaStorageException: I/O exception in append to log
136. pri=ERROR t=kafka-request-handler-6 at=logger Error on broker 1 while processing LeaderAndIsr request with correlationId 8 received from controller 1 epoch 244 java.io.IOException: Map failed at sun.nio.ch.FileChannelImpl.map ... at kafka.utils.CoreUtils$.inLock at kafka.log.AbstractIndex.resize at kafka.log.LogSegment.truncateTo
137. pri=FATAL t=main at=KafkaServerStartable Fatal error during KafkaServerStartable startup. Prepare to shutdown java.io.IOException: Map failed at sun.nio.ch.FileChannelImpl.map ... at kafka.log.AbstractIndex.resize at kafka.log.AbstractIndex.trimToValidSize at kafka.log.LogSegment.recover at kafka.log.Log.recoverLog at kafka.log.Log.loadSegments
138. Another out-of-memory problem? Another memory leak?
139. Memory was not even saturated When brokers crashed
140. [GC pause (G1 Evacuation Pause) (young), 0.0167712 secs] ... [Eden: 420.0M(192.0M)->0.0B(998.0M) Survivors: 12.0M->12.0M Heap: 1809.5M(4096.0M)->1389.5M(4096.0M)] [Times: user=0.28 sys=0.00, real=0.03 secs]
141. $ htop Mem[|||||||||||||||||||||||||||||||||||||||||||||||||||||||||4911/1604MB]
142. pri=ERROR t=kafka-request-handler-6 at=logger Error on broker 1 while processing LeaderAndIsr request with correlationId 8 received from controller 1 epoch 244 java.io.IOException: Map failed at sun.nio.ch.FileChannelImpl.map ... at kafka.utils.CoreUtils$.inLock at kafka.log.AbstractIndex.resize at kafka.log.LogSegment.truncateTo
143. FileChannelImpl.c#Java_..._FileChannelImpl_map0 mapAddress = mmap64(...); if (mapAddress == MAP_FAILED) { if (errno == ENOMEM) { JNU_ThrowOutOfMemoryError(env, “Map failed”); return IOS_THROWN; } return handle(env, -1, “Map failed”); }
144. Kafka internally leverages native memory
145. Not a heap problem
146. Not apparent from GC logs or heap dumps
147. Diagnose by correlating JMX metrics Using various JMX tooling
148. pri=ERROR t=kafka-request-handler-6 at=logger Error on broker 1 while processing LeaderAndIsr request with correlationId 8 received from controller 1 epoch 244 java.io.IOException: Map failed at sun.nio.ch.FileChannelImpl.map ... at kafka.utils.CoreUtils$.inLock at kafka.log.AbstractIndex.resize at kafka.log.LogSegment.truncateTo
150. Not sure if legit
152. Native memory Given that the issue was around
154. Mapped byte buffers growing uncontrollably
155. $ cat /proc/$pid/maps | wc -l
156. That’s a lot of mmaps!
157. Why would this cause a broker to fail?
158. Plenty of memory, disk, and other resources For native memory
159. That was a lie Actually,
160. $ cat /proc/sys/vm/max_map_count
161. $ cat /proc/sys/vm/max_map_count 65535
162. Seems fine?
163. Many partitions per broker Remember that
164. Many log segments Anatomy of a partition, or a log
165. Loaded completely when a broker boots up Each and every one of these log segments must be
166. 64-bit JVM Additional context, no funny business
167. Not enough memory-mapped regions
168. Why does this matter?
169. Brokers survived restarts many times before
170. Not reproducible in staging environment
171. A subtle difference...
172. Log rolling
173. Need enough traffic or retention Enough to force logs to be rolled
174. More log segments
175. More memory mapped files Required on broker bootup
176. Memory looked fine during a sudden crash This is why
177. Brokers would crash during recovery This is why
178. vm.max_map_count={vm_max_map_count} // sysctl.conf $ echo ‘Make memory-mapped regions sufficiently large and keep a buffer.’ The Fix
179. Brokers able to boot successfully again
180. A lot of file descriptors and mmaps
181. Ran with new configuration in staging For completeness, under heavy load for a long period of time Ruled out a potential leak scenario No FD or mmap leaks
182. Everything was fine
183. Wrap up 1 2 3 Heap-Based OOM Automation & Remediation Insufficient Resources ✓
184. Kafka & internals Supports many use cases, many things to configure, scalable Heroku offers fully-managed Apache Kafka Integrated with the Heroku ecosystem Lots to consider when operating at scale An operational undertaking
185. 1 Heap-Based OOM 2 Automation & Remediation 3 Insufficient Resources ✓
186. Challenge 1 How quotas work Release-blocking heap-based OOM bug around quota management and shipped a patch upstream that landed in 0.10.2
187. Challenge 2 How Kafka achieves HA Automation aggressively remediating brokers on recovery
188. Challenge 3 How partitions are implemented What kind of resources are needed More partitions requires more file descriptors and memory-mapped byte buffers
189. Thank you. Jeff Chao jchao [at] heroku.com