pprof – CFC4N的博客

此文为转载，原地址见文章下方。 I have been working with Go for the better part of the year, implementing a scalable blockchain infrastructure at Orbs, and it’s been an exciting year. Over the course of 2018, we researched on which language to choose for our blockchain implementation. This led us to choose Go because of our understanding that it has a good community and an amazing tool-set. In recent weeks we are entering the final stages of integration of our system. As in any large system, the later stage problems which include performance issues, in specific memory leaks, may occur. As we were integrating the system, we realized we found one. In this article I will touch the specifics of how to investigate a memory leak in Go, detailing the steps taken to find, understand and resolve it. The tool-set offered by Golang is exceptional but has its limitations. Touching these first, the biggest one is the limited ability to investigate full core dumps. A full core dump would be the image of the memory (or user-memory) taken by the process running the program. We can imagine the memory mapping as a tree, and traversing that tree would take us through the different allocations of objects and the relations. This means that whatever is at the root is the reason for ‘holding’ the memory and not GCing it (Garbage Collecting). Since in Go there is no simple way to analyze the full core dump, getting to the roots of an object that does not get GC-ed is difficult. At the time of writing, we were unable to find any tool online that can assist us with that. Since there exists a core dump format and a simple enough way to export it from the debug package, it could be that there is one used at Google. Searching online it looks like it is in the Golang pipeline, creating a core dump viewer of such, but doesn’t look like anyone is working on it. Having said that, even without access to such a solution, with the existing tools we can usually get to the root cause. Memory Leaks Memory leaks, or memory pressure, can come in many forms throughout the system. Usually we address them as bugs, but sometimes their root cause may be in design decisions. As we build our system under emerging design principles, such considerations are not believed to be of importance and that is okay. It is more important to build the system in a way that avoids premature optimizations and enables you to perform them later on as the code matures, rather than over engineer it from the get-go. Still, some common examples of seeing memory pressure issues materialize are: Too many allocations, incorrect data representation Heavy usage of reflection or strings Using globals Orphaned, never-ending goroutines In Go, the simplest way to create a memory leak is defining a global variable, array, and appending data to that array. This great blog post describes that case in a good way. So why am I writing this post? When I was researching into this case I found many resources about memory leaks. Yet, in reality systems have more than 50 lines of code and a single struct. In such cases, finding the source of a memory issue is much more complex than what that example describes. Golang gives us an amazing tool called pprof. This tool, when mastered, can assist in investigating and most likely finding any memory issue. Another purpose it has is for investigating CPU issues, but I will not go into anything related to CPU in this post. go tool pprof Covering everything that this tool does will require more than one blog post. One thing that took a while is finding out how to use this tool to get something actionable. I will concentrate this post on the memory related feature of it. The pprof package creates a heap sampled dump file, which you can later analyze / visualize to give you a map of both: Current memory allocations Total (cumulative) memory allocations The tool has the ability to compare snapshots. This can enable you to compare a time diff display of what happened right now and 30 seconds ago, for example. For stress scenarios this can be useful to assist in locating problematic areas of your code. pprof profiles The way pprof works is using profiles. A Profile is a collection of stack traces showing the call sequences that led to instances of a particular event, such as allocation. The file runtime/pprof/pprof.go contains the detailed information and implementation of the profiles. Go has several built in profiles for us to use in common cases: goroutine — stack traces of all current goroutines heap — a sampling of memory allocations of live objects allocs — a sampling of all past memory allocations threadcreate — stack traces that led to the creation of new OS threads block — stack traces that led to blocking on synchronization primitives mutex — stack traces of holders of contended mutexes When looking at memory issues, we will concentrate on the heap profile. The allocs profile is identical in regards of the data collection it does. The difference between the two is the way the pprof tool reads there at start time. Allocs profile will start pprof in a mode which displays the total number of bytes allocated since the program began (including garbage-collected bytes). We will usually use that mode when trying to make our code more efficient. The heap In abstract, this is where the OS (Operating System) stores the memory of objects our code uses. This is the memory which later gets ‘garbage collected’, or freed manually in non-garbage collected languages. The heap is not the only place where memory allocations happen, some memory is also allocated in the Stack. The Stack purpose is short term. In Go the stack is usually used for assignments which happen inside the closure of a function. Another place where Go uses the stack is when the compiler ‘knows’ how much memory needs to be reserved before run-time (e.g. fixed size arrays). There is a way to run the Go compiler so it will output an analysis of where allocations ‘escape’ the stack to the heap, but I will not touch that in this post. While heap data needs to be ‘freed’ and gc-ed, stack data does not. This means it is much more efficient to use the stack where possible. This is an abstract of the different locations where memory allocation happens. There is a lot more to it but this will be outside the scope for this post. Obtaining heap data with pprof There are two main ways of obtaining the data for this tool. The first will usually be part of a test or a branch and includes importing runtime/pprof and then calling pprof.WriteHeapProfile(some_file) to write the heap information. Note that WriteHeapProfile is syntactic sugar for running: // lookup takes a profile namepprof.Lookup("heap").WriteTo(some_file, 0) According to the docs, WriteHeapProfile exists for backwards compatibility. The rest of the profiles do not have such shortcuts and you must use the Lookup() function to get their profile data. The second, which is the more interesting one, is to enable it over HTTP (web based endpoints). This allows you to extract the data adhoc, from a running container in your e2e / test environment or even from ‘production’. This is one more place where the Go runtime and tool-set excels. The entire package documentation is found here, but the TL;DR is you will need to add it to your code as such: import ( "net/http" _ "net/http/pprof") ... func main() { ... http.ListenAndServe("localhost:8080", nil)} The ‘side effect’ of importing net/http/pprof is the registration the pprof endpoints under the web server root at /debug/pprof. Now using curl we can get the heap information files to investigate: curl -sK -v http://localhost:8080/debug/pprof/heap > heap.out Adding the http.ListenAndServe() above is only required if your program did not have a http listener before. If you do have one it will hook on it and there is no need to listen again. There are also ways to set it up using a ServeMux.HandleFunc() which would make more sense to a more complex http-enabled program. Using pprof So we have collected the data, what now? As mentioned above, there are two main memory analysis strategies with pprof. One is around looking at the current allocations (bytes or object count), called inuse. The other is looking at all the allocated bytes or object count throughout the run-time of the program, called alloc. This means regardless if it was gc-ed, a summation of everything sampled. This is a good place to reiterate that the heap profile is a sampling of memory allocations. pprof behind the scenes is using the runtime.MemProfile function, which by default collects allocation information on each 512KB of allocated bytes. It is possible to change MemProfile to collect information on all objects. Note that most likely, this will slow down your application. This means that by default, there is some chance that a problem may happen with smaller objects that will slip under pprof’s radar. For a large codebase / long-running program, this is not an issue. Once we collected the profile file, it is time to load it into the interactive console pprof offers. Do so by running: > go tool pprof heap.out Let's observe the information displayed Type: inuse_spaceTime: Jan 22, 2019 at 1:08pm (IST)Entering interactive mode (type "help" for commands, "o" for options)(pprof) The important thing to note here is the Type: inuse_space . This means we are looking at allocation data of a specific moment (when we captured the profile). The type is the configuration value of sample_index, and the possible values are: inuse_space — amount of memory allocated and not released yet inuse_object s— amount of objects allocated and not released yet alloc_space — total amount of memory allocated (regardless of released) alloc_objects — total amount of objects allocated (regardless of released) Now type top in the interactive, the output will be the top memory consumers We can see a line telling us about Dropped Nodes, this means they are filtered out. A node is an object entry, or a ‘node’ in the tree. Dropping nodes is a good idea to reduce some noise, but sometimes it may hide the root cause of a memory issue. We will see an example of that as we continue our investigation. If you want to include all data of the profile, add the -nodefraction=0 option when running pprof or type nodefraction=0 in the interactive. In the outputted list we can see two values, flat and cum. flat means that the memory allocated by this function and is held by that function cum means that the memory was allocated by this function or function that it called down the stack This information alone can sometimes help us understand if there is a problem. Take for example a case where a function is responsible of allocating a lot of memory but is not holding it. This would mean that some other object is pointing to that memory and keeping it allocated, meaning we may have a system design issue or a bug. Another neat trick about top in the interactive window is that it is actually running top10. The top command supports topN format where N is the number of entries you want to see. In the case pasted above, typing top70 for example, would output all nodes. Visualizations While the topN gives a textual list, there are several very useful visualization options that come with pprof. It is possible to type png or gif and many more (see go tool pprof -help for a full list). On our system, the default visual output looks something like: This may be intimidating at first, but it is the visualization of memory allocation flows (according to stack traces) in a program. Reading the graph is not as complicated as it looks. A white square with a number shows allocated space (and the cumulative of how much memory it’s taking right now on the edge of the graph), and each wider rectangle shows the allocating function. Note that in the above image, I took a png off a inuse_space execution mode. Many times you should also take a look at inuse_objects as well, as it can assist with finding allocation issues. Digging deeper, finding a root cause So far, we were able to understand what is allocating memory in our application during runtime. This helps us get a feeling of how our program behaves (or misbehaves). In our case, we could see that memory is retained by membuffers, which is our data serialization library. This does not mean that we have a memory leak at that code segment, it means that the memory is being retained by that function. It is important to understand how to read the graph, and the pprof output in general . In this case, understanding that when we serialize data, meaning that we allocate memory to structs and primitive objects (int, string), it is never released. Jumping to conclusions or misinterpreting the graph, we could have assumed that one of the nodes on the path to serialization is responsible to retaining the memory, for example: subset of the graph Somewhere in the chain we can see our logging library, responsible for >50MB of allocated memory. This is memory which is allocated by functions called by our logger. Thinking it through, this is actually expected. The logger causes memory allocations as it needs to serialize data for outputting it to the log and thus it is causing memory allocations in the process. We can also see that down the allocation path, the memory is only retained by serialization and nothing else. Additionally, the amount of memory retained by the logger is about 30% of the total. The above tells us that, most likely, the problem is not with the logger. If it was 100%, or something close to it, then we should have been looking there — but it’s not. What it could mean is that something is being logged that shouldn’t be, but it is not a memory leak by the logger. This is a good time to introduce another pprof command called list. It accepts a regular expression which will be a filter of what to list. The ‘list’ is in actual the annotated source code related to the allocation. In the context of the logger which we are looking into, we will execute list RequestNew as we would like to see the calls made to the logger. These calls are coming from two functions which happen to begin with the same prefix. We can see that the allocations made are sitting in the cum column, meaning the memory allocated is retained down the call stack. This correlates to what the graph also shows. At that point it is easy to see that the reason the logger was allocating the memory is because we sent it the entire ‘block’ object. It needed to serialize some parts of it at the very least (our objects are membuffer objects, which always implement some String() function). Is it a useful log message, or good practice? Probably not, but it is not a memory leak, not at the logger end or the code which called the logger. list can find the source code when searching for it under your GOPATH environment. In cases where the root it is searching for does not match, which depends on your build machine, you can use the -trim_path option. This will assist with fixing it and letting you see the annotated source code. Remember to set your git to the right commit which was running when the heap profile was captured. So why is memory retained? The background to this investigation was the suspicion that we have a problem — a memory leak. We came to that notion as we saw memory consumption was higher than what we would expect the system to need. On top of that, we saw it ever increasing, which was another strong indicator for ‘there is a problem here’. At this point, in the case of Java or .Net, we would open some ‘gc roots’ analysis or profiler and get to the actual object which is referencing to that data, and is creating the leak. As explained, this is not exactly possible with Go, both because of a tooling issue but also because of Go’s low level memory representation. Without going into details, we do not think Go retains which object is stored at which address (except for pointers maybe). This means that in actual, understanding which memory address represents which member of your object (struct) will require some sort of mapping to the output of a heap profile. Talking theory, this could mean that before taking a full core dump, one should also take a heap profile so the addresses can be mapped to the allocating line and file and thus the object represented in the memory. At this point, because we are familiar with our system, it was easy to understand this is not a bug anymore. It was (almost) by design. But let’s continue to explore how to get the information from the tools (pprof) to find the root cause. When setting nodefraction=0 we will get to see the entire map of the allocated objects, including the smaller ones. Let’s look at the output: memory visualization with nodefraction=0 We have two new subtrees. Reminding again, pprof heap profile is sampling memory allocations. For our system that works — we are not missing any important information. The longer new tree, in green, which is completely disconnected from the rest of the system is the test runner, it is not interesting. system was configured to “leak” ? The shorter one, in blue, which has an edge connecting it to the entire system is inMemoryBlockPersistance . That name also explains the ‘leak’ we imagined we have. This is the data backend, which is storing all data in memory and not persisting to disk. Whats nice to note is that we could see immediately that it is holding two large objects. Why two? Because we can see the object is of size 1.28MB and the function is retaining 2.57MB, meaning two of them. The problem is well understood at this point. We could have used delve (the debugger) to see that this is the array holding all blocks for the in-memory persistence driver we have. So what could we fix? Well, that sucked, it was a human error. While the process was educating (and sharing is caring), we did not get any better, or did we? There was one thing that still ‘smelled’ about this heap information. The deserialized data was taking up too much memory, why 142MB for something that should be taking substantially less? . . pprof can answer that — actually, it exists to answer such questions exactly. To look into the annotated source code of the function, we will run list lazy. We use lazy, as the function name we are looking for is lazyCalcOffsets() and we know no other functions in our code begin with lazy. Typing list lazyCalcOffsets would work as well of course. We can see two interesting pieces of information. Again, remember that pprof heap profile samples information about allocations. We can see that both the flat and the cum numbers are the same. This indicates that the memory allocated is also retained by these allocation points. Next, we can see that the make() is taking some memory. That makes sense, it is the pointer to the data structure. Yet we also see the assignment at line 43 is taking up memory, meaning it creates an allocation. This educated us about maps, where an assignment to a map is not a straightforward variable assignment. This article goes into great detail on how map works. In short a map has an overhead, and the more elements the bigger this overhead is going to ‘cost’ when comparing to a slice. The following should be taken with a grain of salt: It would be okay to say that using a map[int]T, when the data is not sparse or can be converted to sequential indices, should usually be attempted with a slice implementation if memory consumption is a relevant consideration. Yet, a large slice, when expanded, might slow down an operation, where in a map this slowdown will be negligible. There is no magic formula for optimizations. In the code above, after checking how we used that map, we realized that while we imagined it to be a sparse array, it came out as not so sparse. This matches the above argument and we could immediately see that a small refactor of changing the map to a slice is actually possible, and might make that code more memory efficient. So we changed it to: As simple as that, instead of using a map we are now using a slice. Because of the way we receive the data which is lazy loaded into it, and how we later access that data, other than these two lines and the struct holding that data, no other code change was required. What did it do to the memory consumption? Let’s look at the benchcmp for just a couple of tests The read tests initialize the data structure, which creates the allocations. We can see that runtime improved by ~30%, allocations are down by 50% and memory consumption by >90% (!) Since the map, now-slice, was never filled with a lot of items, the numbers pretty much show what we will see in production. It depends on the data entropy, but there may be cases where both allocations and memory consumption improvements would have been even greater. Looking at pprof again, and taking a heap profile from the same test we will see that now the memory consumption is in fact down by ~90%. The takeaway will be that for smaller data sets, you shouldn’t use maps where slices would suffice, as maps have a large overhead. Full core dump As mentioned, this is where we see the biggest limitation with tooling right now. When we were investigating this issue we got obsessed with being able to get to the root object, without much success. Go evolves over time at a great pace, but that evolution comes with a price in the case of the full dump or memory representation. The full heap dump format, as it changes, is not backwards compatible. The latest version described here and to write a full heap dump, you can use debug.WriteHeapDump(). Albeit right now we do not find ourselves ‘stuck’ because there is no good solution for exploring full dumps. pprof answered all our questions until now. Do note, the internet remembers a lot of information which is no longer relevant. Here are some things you should ignore if you are going to try and open a full dump yourself, as of go1.11: There is no way to open and debug a full core dump on MacOS, only Linux. The tools at https://github.com/randall77/hprof are for Go1.3, there exists a fork for 1.7+ but it does not work properly either (incomplete). viewcore at https://github.com/golang/debug/tree/master/cmd/viewcore does not really compile. It is easy enough to fix (packages in the internal are pointing to golang.org and not github.com), but, it does not work either, not on MacOS, maybe on Linux. Also https://github.com/randall77/corelib fails on MacOS pprof UI One last detail to be aware of when it comes to pprof, is its UI feature. It can save a lot of time when beginning an investigation into any issue relating to a profile taken with pprof. go tool pprof -http=:8080 heap.out At that point it should open the web browser. If it does not then browse to the port you set it to. It enables you to change the options and get the visual feedback much faster than you can from the command line. A very useful way to consume the information. The UI actually got me familiar with the flame graphs, which expose culprit areas of the code very quickly. Conclusion Go is an exciting language with a very rich toolset, there is a lot more you can do with pprof. This post does not touch CPU profiling at all, for example. Some other good reads: https://rakyll.org/archive/ — I believe this to be one of the go contributors around performance monitoring, a lot of good posts at her blog https://github.com/google/gops — written by JBD (who runs rakyll.org), this tool warrants its own blog post. https://medium.com/@cep21/using-go-1-10-new-trace-features-to-debug-an-integration-test-1dc39e4e812d — go tool trace which is around CPU profiling, this is a great post about that profiling feature. 原文地址：How I investigated memory leaks in Go using pprof on a large codebase

背景： etcd 3.2.23 golang 1.9.1 centos 6 etcd cluster集群节点7台，节点member之间 https 通讯，与 client 之间也是 https 通讯测试环境 2W 台主机，每台都要安装这个 agent，每个 agent注册一个包含lease的key,key的 ttl 设置为10s 设置keepalive 产品等着发布上线，持续遇到集群性能问题，长时间找不到原因，感觉我要崩溃了集群性能问题不解决，线上更多的服务器更是没法部署，领导不认可，不满意，我就要被开除了，我就要辞职了。。。 Etcd github官方提了issue，官方没时间帮我们看（理解官方的苦衷，issue 太多，很多都是使用者的问题）... 问题现象：带有lease id的 key 无故丢失 leader节点大部分时间 TIME-WAIT数量非常高 leader 节点的 CLOSE-WAIT 有时也非常高 leader 的 CPU 使用率持续在80-90%的样子 leader 节点的内存使用率持续上升，疑似内存泄露的症状监控图如下: etcd leader的 etcd 进程入手：先分析「疑似内存溢出」问题，在 etcd 里，已经有pprof的信息，golang的tool里也有直接读取 http pprof 性能分析的工具，只是不支持 https 的。需要将 pprof 文件下载到本地，再从本地读取结果如下：可以看到大量 math 相关的包函数占用了大量的 cpu，而我们程序的业务中，并不涉及数学计算相关业务，也不会引用 math 包。唯一可能性就是在 https 的 tls 证书在做 RSA 算法校验时，用到了大量数学计算。我把 pprof 导出问 svg 图确认了一下，确实是 tls 的证书计算占用了大量 CPU。但是 https 的链接，不应该是建立1次后就不再建立了吗？为什么会有这么大量的 cpu 计算呢。难道 TIMEWAIT 这么高跟这个有关系吗？回到 TIMEWAIT 的问题上来，此刻，leader 节点是 xxxx-etcdserver-xxx02，且TIME_WAIT非常高 leader 节点上的time-wait来源，都是来自各个member节点，平均每个节点将近几万个 TIMEWAIT，相隔几秒再次查询，还是5万多个。而各个 member 节点上，查到的是跟 leader 节点的2380端口保持1千多个 ESTABLISHED 状态的连接，也确实是频繁的创建链接。为什么member节点频繁的创建链接呢？tcpdump抓点TCP 通讯包看一下: 如上抓包的图，发现了什么？ 120140 2018-06-22 20:37:30.219 10.72.198.234 74 10.20.127.136 TCP 12902 → etcd-server(2380) [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=3008487334 TSecr=0 WS=128 120141 2018-06-22 20:37:30.219 10.20.127.136 74 10.72.198.234 TCP etcd-server(2380) → 12902 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=2796204056 TSecr=3008487334 WS=128 120362 2018-06-22 20:37:30.242 10.72.198.234 66 10.20.127.136 TCP 12902 → etcd-server(2380) [ACK] Seq=1 Ack=1 Win=14720 Len=0 TSval=3008487358 TSecr=2796204056 120368 2018-06-22 20:37:30.242 10.72.198.234 204 10.20.127.136 TCP 12902 → etcd-server(2380) [PSH, ACK] Seq=1 Ack=1 Win=14720 Len=138 TSval=3008487358 TSecr=2796204056 120369 2018-06-22 20:37:30.242 10.20.127.136 66 10.72.198.234 TCP etcd-server(2380) → 12902 [ACK] Seq=1 Ack=139 Win=15616 Len=0 TSval=2796204080 TSecr=3008487358 174076 2018-06-22 20:37:40.242 10.72.198.234 66 10.20.127.136 TCP 12902 → etcd-server(2380) [FIN, ACK] Seq=139 Ack=1 Win=14720 Len=0 TSval=3008497358 TSecr=2796204080 174377 2018-06-22 20:37:40.282 10.20.127.136 66 10.72.198.234 TCP etcd-server(2380) → 12902 [ACK] Seq=1 Ack=140 Win=15616 Len=0 TSval=2796214120 TSecr=3008497358 从这些数据包中，你能看出什么问题？想一想，打开这张图，想5分钟再往下看。。。 120140是10.72.198.234 的 member 节点作为客户端，向10.20.127.136的2380的 leader 节点发起TCP 连接请求。 120141是 leader 回的握手确认包。120362是 member 发的 ACK 握手完成确认包。这些都很简单明了。 120368是 member 向 leader 发的数据包，120369是 leader 回 member 收到前面数据包的 ack。嗯，这些也很好明白。 174076是什么？ member向 leader 发的FIN 关闭 TCP 连接的数据包，为什么？为什么member要关闭连接？再抽查几个数据包看看，从 “专家信息”里预览的1000多个“SYN”里找.... 可以看出，都是 member主动向 leader 发 FIN 关闭包，这是为什么呢？仅仅是看出来这些吗？有没有注意到 member 发的消息包，收到 leader 回的 ack 之后，距离 member 主动发的 FIN 之间的时间间隔？都是10s ？为什么是10s？ leader 回了 ack，但没主动向 member 发“FIN,ACK”，为什么没回呢？若没回，那么 leader 上的这个 TCP 五元组的状态是什么？是的，是“CLOSE-WAIT”，难道这就是造成leader上大量 CLOSE-WAIT 的原因？先怀疑一下，继续往下看... 如上所说，member 向 leader 发了一个PSH数据包，发来什么内容呢？为什么 leader 没回信息？ payload的总长度是138，完全看不出来是什么数据包？不，应该还是有眼熟的，看前3个字节，0x16,0x03,0x01，如果对 HTTPS 熟悉的话，会联想到这是 TLS 的magic number，0x16对应十进制的22 即“Client Hello 的 Handshake”，后面的0x31,0x01是 TLS 的版本号。再配合我们的 member 跟 leader 之间确实是 https 通讯，可以确定这个地方是 tls 的client Hello握手包。也就是说配合前面发现的 10s 的间隔，可以看出 member 与 leader 之间的 TLS 握手并未完成，leader 并没有回 Server Hello... 整个TCP 包比较短，没有发现其他有用的信息... 去掉 HTTPS，减轻 cpu 负担：回到之前的 CPU pprof 情况来看，是 TLS 相关证书计算，导致 CPU 使用率较高，但大量的 TCP 连接的发起，才是导致大量 TLS 计算的原因，导致内存飙升，消息积压的原因。不过，我们还是尝试去掉 member 与 leader 时间的 tls 证书校验，尝试减轻 leader 的CPU 使用。但结果影响不大，CPU 使用率依旧很高，不过，这也在意料之中，毕竟不是问题根本原因，查看pprof 如下 CPU 使用率较高的，是 runtime.futex 跟系统调用的 syscall.Syscall，以及runtime下的包，heapBitsForObject、scanobject、greyobject是 golang GC 时的运行时函数，意味着GC 已经占用很大的 CPU 了。配合memory pprof来看下如上，可以看出，大约65%的内存都用在了recvBuffer.put 这里的 put 方法是将收到的recvMsg写入到b.backlog这个 slice 中的，func (b recvBuffer) put(r recvMsg)跟 (b recvBuffer) load()两个函数都对b.backlog有读写操作，也就是说，这个slice 写入、读取时，都会进行加锁，严重占用 CPU 以及影响性能，增大系统负载。而且若 (b recvBuffer) load()处理速度跟不上func (b recvBuffer) put(r recvMsg)写入速度，意味着这个slice会持续增长，造成看似内存溢出的现象。。。那问题来了，func (b recvBuffer) put(r recvMsg)为什么有这么大的调用量，为什么在频繁写入...为什么呢？？？定位到内存溢出的疑似原因： grpc/server.go func (s Server) serveStreams(st transport.ServerTransport) grpc/transport/handler_server.go 文件284行 func (ht serverHandlerTransport) HandleStreams 函数中的334行然后再走到了，func (b *recvBuffer) put(r recvMsg)函数里，也就是说，这里的消息slice堆积，是因为接收到了大量http request。那接下来就是要找到这些http request 是来自谁了？阅读 etcd 源码：配合 member 之间大量的 TCP TIME-WAIT 状态链接，排查方向改到 member 节点上。要查找 etcd member 建立 TCP/HTTP 链接的地方，在源码里，还是非常多的，一时间没找到更好的bug 定位方式，只要从etcd 源码去逐步分析排查。 etcdmain/main.go 39行 startEtcdOrProxyV2() etcdmain/etcd.go 103行 startEtcd() etcdmain/etcd.go 186行 embed.StartEtcd(cfg) embed/etcd.go 107行 startPeerListeners() ，用 rafthttp.NewListener 创建了一个Listener。用于 etcd member 之间通讯。依赖github.con/coreos/etcd/pkg/transport包 embed/etcd.go 110行 startClientListeners() 用 net.Listen 创建了一个Listener。用于 client 跟 member 之间通讯。keepalive 使用github.con/coreos/etcd/pkg/transport包 157行 etcdserver.NewServer() 对本地配置读取，数据库目录读取，设置mvcc多版本控制函数，设置 lease 租约续期函数等等 166行 e.servePeers() 进行对 Linster 启动 Serve 接受请求 317行 etcdhttp.NewPeerHandler(e.Server) 设置HTTP Handler，里面函数如下：如上，etcd 节点之间的通讯，设定了这几个Handler "/" --> http.NotFound "/raft"、"/raft/" --> raftHandler "/members" --> mh "/leases/internal" 、 "/leases" --> raftHandler "/version" --> versionHandler 也就是说，member 之间通讯的大量通讯只会是这些 handler 中间的一个，除非源码找漏了。。。从这个开源产品功能特性上来看，member 之间需要大量同步的，应该就是数据了，应该把线索放到raftHandler上吗？头大.... raftHandler是s.RaftHandler() 返回的，值是 EtcdServer.r.transport.Handler()返回值。 EtcdServer.r是在etcdserver/server.go的414行赋值的 etcdserver/server.go 的511行 EtcdServer.r.transport = tr进行赋值，类型为rafthttp.Transport ，其Handler 如下代码：这里又有几个 Handler ，而且都是 raft 处理相关的，代码读起来比较吃力，很难理解作者意图，打印http.dial堆栈：要想从这里查找 TCP 连接的发起代码，恐怕是难上加难，所以，我换了个思路，直接在 TCP 连接 Dail 的地方，判断 addr 是 etcd leader 的地址，打印调用栈。使用 runtime/debug下的debug.PrintStack()函数输出。同时打印了连接完成后的remote.addr，用于校对。不过，这改动是 golang 的系统 runtime 类库，(改了系统库，记得改回来)。要小心谨慎，在http/transport.go 882行增加如下重新编译 etcd server，替换到集群中的某一个 member 节点上。开始压测这个节点，重现大量 TIME-WAIT 的现象。现象重现后，在日志里也拿到了运行堆栈在压测时，我用 netstat 抽样打印几次当前 member 上的 TCP 连接信息数据，也是用于校对日志输出的数据。在压测的日志数据里，每建立一个 TCP 连接，都打印了这些堆栈，并且打印了远程 IP 的地址、端口。跟前面抽样打印的 TCP 数据核对一下，发现连接 leader 2380端口的几个 TCP 连接五元组跟上面打印的remote.addr的五元组一致。也就是说，是这个函数创建了大量的从 member 到 leader 之间的 TCP 连接。好了，如果找到大量 TCP 连接发起的函数了，又找到了该函数的调用栈了，那岂不是找到问题了？然而，事情并没有这么简单，在上面的调用栈日志里，只能定位到coreos/etcd/pkg/transport.(*rwTimeoutDialer).Dial，并不能打印出所有调用堆栈，为什么？找到 etcd member 10s 后主动断开 TCP 连接的原因：在系统类库里的net/http/transport.go的Transport.dial方法中，如果该Transport自定义了Dial方法，则调用自定义的...这个自定义的Dial方法是在github.com/coreos/etcd/pkg/transport/transport.go里定义的，如下: 在代码dial := func(net, addr string) (net.Conn, error) ... 这里，自定义了一个 Dial 方法，赋值到http.Transport.Dial 函数属性上，并且设定TLS 的超时时间是 TLSHandshakeTimeout: 10 time.Second，这也就是之前抓包时，看到的10s 后，member 节点主动断开连接的原因----超过 TLS 设定的timeout时间了。函数NewTransport的调用地方，只在NewTimeoutTransport这里找到，如下：也就是说，找到NewTimeoutTransport调用着，就能确定发起大量 TCP 的代码...但之前的堆栈打印，并没有打印到这些函数调用，只好再想其他办法。在NewTimeoutTransport的代码里，有一句对 HTTP Keepalive的最大持有空闲长连接数字的设置tr.MaxIdleConnsPerHost = 1024，这个参数决定 golang 的 http client 包对 server 发起 http 请求时，能持有的最大空闲 TCP 连接数量，在 etcd 的代码里，被设置为1024了，也就是说，etcd member 跟 etcd leader 之间空闲时，持有TCP 连接数可以是1024个，便于下次复用。（插一句，有人说，http 是最好的 RPC，这里我是不认同的，光从TCP 连接复用上，就有非常大的差异，在http 1.1 TCP 链接「另类」复用，http 1.1 的keepalive属性也是仅当前一个请求响应后，这个链接才能继续复用，请求响应串行化。而在 http2里，是不需要等待上一个请求返回的，才有真正意义上的多路复用见：Streams and Multiplexing ，如果你做过 rpc 的功能实现，你就知道 rpc 在 tcp 上是如何实现请求响应的一一对应的，你就能很快明白http2\http1.1的 TCP 链接复用的区别了。）排查 etcd member 跟 etcd leader 之间的通讯：回到正题，对于代码这里的定位，我尝试去阅读代码来协助定位，但 etcd 的源码太复杂了，我读到 raft 协议节点之间数据同步这块，卡住了。开始从其他路子尝试解决，之前的 cpu 占用较高问题，我们在 member 节点之间去掉了 tls 证书验证，那么我们在 member 上做 tcp 抓包，抓2380端口数据包，看看数据发送的都是什么内容。数据包中，可以看出 member 向 leader 上发送了大量的 /leases的 POST 请求。根据这个 uri，找到发起 HTTP 请求的代码，在etcdserver/v3_server.go的252行阅读这段代码，可以看到函数调用leasehttp.RenewHTTP将请求发送到leader.PeerURLs，即发送到 leader 节点上。继续跟进leasehttp.RenewHTTP，可以看出，该请求使用 golang 标准包的http.Client.Do来将请求发送出去。http.Client.Transport使用参数传入的rt http.RoundTripper。定位到10s TLS timeout 的相关函数调用：回到上一层代码 s.peerRt参数来自*EtcdServer.peerRt，在etcdserver/server.go的429行被赋值peerRt: prt prt变量在该文件的288行被赋值prt, err := rafthttp.NewRoundTripper(cfg.PeerTLSInfo, cfg.peerDialTimeout()) rafthttp.NewRoundTripper函数调用rafthttp.NewTimeoutTransport 没错，rafthttp.NewTimeoutTransport调用了rafthttp.NewTransport函数，也就是之前堆栈打印时，发现大量 TCP 链接创建使用的这个函数，也就是10s TLS timeout 的地方。这里可以关联上了，确认大量发起 TCP 连接的代码调用关系，证明方向正确，剩下的就是顺藤摸瓜，找到发起大量请求的原因即可。回到LeaseRenew函数调用的地方，调用func (s *EtcdServer) LeaseRenew函数代码见github.com/coreos/etcd/etcdserver/api/v3rpc/lease.go的88行附近 71行 func (ls *LeaseServer) LeaseKeepAlive函数调用func (ls *LeaseServer) leaseKeepAlive() etcdserver/etcdserverpb/rpc.pb.go的3417行func _Lease_LeaseKeepAlive_Handler(srv interface{}, stream grpc.ServerStream)调用了func (ls *LeaseServer) LeaseKeepAlive函数 etcdserver/etcdserverpb/rpc.pb.go的3480行将函数_Lease_LeaseKeepAlive_Handler设置为 StreamName: "LeaseKeepAlive"的 Handler，在通过*grpc.Server的RegisterService方法，在启动时，注册到监听器中 leaseKeepAlive函数是一个事件循环，从stream.Recv()拿到数据，则进行发送到 leader 节点上 stream.Recv()函数是google.golang.org/grpc/stream.go中的函数，这个不是 etcd 官方自己的代码，而是另外一个开源项目，意味着我还需要再把这块代码再阅读阅读，理解理解。通过漫长的阅读，可以看到这里收到的消息都是来自 client 发送来的消息，其实可以从变量命名上看到端倪，比如 client 跟 member 之间通讯处理的变量都包含stream字样，而member到 leader 或 member 节点之间都带有peer字样，其实，client 跟 etcd 节点之间通讯用的是 http2传输协议，消息编码用的是grpc+protobuf；而etcd member节点之间是http1.1传输，消息编码也是 protobuf。 etcd lease 租约续期的时机：就是说，这里的大量lease 租约续期的请求，来自 client 的请求，在我的案例中，我把主机 lease 的 TTL 设置为10S，这块会有异常吗？client 的 lease 续期是谁来发送？client 自己吗？多久发送一次？过期前的1秒？在 etcd 的 client 类库中，对于租约续期的代码在clientv3/lease.go的474行 nextKeepAlive变量是 lease TTL 的三分之一，用于下次续期时的触发时刻，在后面的sendKeepAliveLoop函数续期时，回每隔500ms 进行一次循环，检测是否续期。也就是说，我们场景下，10s 的 TTL 会每隔3S 一次续期。3W 客户端的话，每秒1W 的写请求，而之前我们压测结果是集群节点可以有4W 以上的 (官方压测数据)qps，不至于这点都撑不住。这是个疑点。不过，前面的分析判断，大量的续约续期导致大量 TCP 链接的建立，大量 TCP 链接的建立，导致 leader 节点上大量对象分配，大量内存申请，golang gc 时，消耗大量 CPU，那这个问题也应该要优化一下，为此，我们把 TTL 设定为600S，即10分钟，也就是说，会在200秒后进行一次续期。扩大lease TTL，尝试优化集群负载: 修复后的版本，我们在线下发布了6000多台，观察效果，果然，在发布后，内存有明显的下降，CPU 指标也有，但是在1个小时后，指标又上升了。。。问题依旧：这是为什么呢？中间大约1个小时的负载指标下降是因为发布过程带来的假象吗？上次变更的 lease 有效果吗？可我更改时，是测试过的，测试报告都有呢----agent 的 etcd lease租约时长调整，TTL 续期是200S 一次了，但这是为什么？为了确认这个问题，我在其中一台 member 上抓包确认上面确实是大量的 lease 包，那么每个 lease id 之间的发送间隔是多少？是我们预期的200秒吗？或者这些 lease 包是同一个 lease id 吗？一共有多少个 lease id 呢？分析 tcpdump 的pcapng文件：之前从 etcd 的源码分析可以看出，etcd node 节点之间的通讯消息编码也是 protobuf 的，我们需要把 http response body 的字节流复制出来，用 protobuf 的对应结果体解码即可。可是从 2018-07-05 16:38:31.015981 到 2018-07-05 16:43:20.420401 之间，间隔5分钟之间，一共103万个数据包，手动复制，实在没法统计。借用pcap包，对整个 tcpdump抓包的pcapng文件，分析，过滤响应类型是application/protobuf的，取 http response body内容，并对其做 pb.LeaseKeepAliveRequest protobuf的结构体解析，计算 lease 总数与唯一数运行结果： lease id 总数数: 77550, lease id 唯一数:1382。这些结果说明，相同的 lease id 在频繁发送续约请求。再次写程序，把这些 lease id 取出来，到 etcd 集群上查看 TTL 剩余时间是否是预期的400-600秒之间，但结果却总是599秒，以其中一个 lease id 为例，每隔1秒去抓取 TTL 信息，但每次结果 TTL 都是599秒， grantTTL 是600，意味着 etcd member 持续不断的为这些 lease id 不停的续期。我们之前排查结果是， member 的续期是来自 client 的 lease keepalive 请求，那么方向得放到 client 上。抽查其中一台 client，抓包分析，也确实是在频繁发送/etcdserverpb.Lease/LeaseKeepAlive 请求，这就很奇怪，跟之前我的测试结果完全不一样，明明测试时，是每个200S 一起续期请求，为什么这里变得这么频繁，每秒都发起。回到 etcd clientv3的代码上：现象很奇怪，排查这个问题，只能再次从源码层面入手，方向也放到 /etcdserverpb.Lease/LeaseKeepAlive的地方，函数sendKeepAliveLoop这里开始循环处理判断是否需要续期租约如上代码，每隔 500毫秒一次循环，遍历l.keepAlives map，判断每个LeaseID的nextKeepAlive是否到了，client 决定是否发起LeaseKeepAliveRequest。这个nextKeepAlive的赋值是在clientv3/lease.go的recvKeepAlive函数内，第473行是的，这块代码之前看过，之前关注的只是 TTL 时间的设定，但仔细看看这段代码ka.nextKeepAlive = nextKeepAlive，这里做下一次lease 续期的赋值，判断方法是select case，判断条件是ch <- karesp，在 golang 里，这种写法表示该channle能写入的话，则进入case里面的流程，对ka.nextKeepAlive进行赋值；否则不赋值。。。否则，不赋值。。。否则，不赋值。。。那么，这么 channel 长度多少呢？会不会写入的速度大于读取导致没写进去，导致下一次的续期时间没赋值成功呢？继续追查，在clientv3/lease.go的222行KeepAlive函数里 ch := make(chan *LeaseKeepAliveResponse, leaseResponseChSize)进行chan 的申请，长度leaseResponseChSize是常量，值是16。chs是个slice，长度1，只有这一个。那么，接下来，去确认这个 ch 读取的代码吧，可是我读完整个 lease.go也没找到哪里读取这个 channel 的代码，除了几处 close 的回收操作。那问题来了，会不会是这里把 ch channel 写满了，就无法再写入进去，导致ka.nextKeepAlive = nextKeepAlive流程走不到，导致ka.nextKeepAlive一直是上次的过去的续期时间，导致频繁进行续期呢？找到疑点，每秒2次 lease keepalive 的请求：开始测试，在 ch channel 写入的 default 分支里，打印“无法写入”等字样，并在for 后面打印这个ka的 TTL 等信息，用于核对。log.Println(fmt.Sprintf("karesp.TTL:%d, nextKeepAlive:%s,ka.nextKeepAlive:%s, ka.deadline:%s",karesp.TTL, nextKeepAlive.String(),ka.nextKeepAlive.String(), ka.deadline.String())) 改动后，重新编译代码，上传至某台 client 上，关掉 DEBUG 模式，观察日志输出。文件见 /xxxx/xxx/core/nohup.out.1 ，在 2018/07/05 21:10:42 启动程序，经过1个多小时的观察，果然在2018/07/05 22:04:05时，lease 续约续期的请求从200秒变成了每秒2次。同时到 etcd 集群上查询响应 lease id，发现 TTL 均为599，grantTTL 为600，则可说明是客户端在频繁重新发送租约请求。第一个版本没打印ka.nextKeepAlive ,调整后，重新打印，为了让等待时间变短些，我把600s 改成60，便于观察。得到如下日志 2018/07/05 22:40:02 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:40:02 karesp.TTL:60, nextKeepAlive:2018-07-05 22:40:22.811626819 +0800 CST m=+40.135091508,ka.nextKeepAlive:2018-07-05 22:40:22.811626819 +0800 CST m=+40.135091508, ka.deadline:2018-07-05 22:41:02.811627601 +0800 CST m=+80.135092217 2018/07/05 22:40:22 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:40:22 karesp.TTL:60, nextKeepAlive:2018-07-05 22:40:42.922698966 +0800 CST m=+60.246163715,ka.nextKeepAlive:2018-07-05 22:40:42.922698966 +0800 CST m=+60.246163715, ka.deadline:2018-07-05 22:41:22.922699917 +0800 CST m=+100.246164470 2018/07/05 22:40:43 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:40:43 karesp.TTL:60, nextKeepAlive:2018-07-05 22:41:03.330494852 +0800 CST m=+80.653959932,ka.nextKeepAlive:2018-07-05 22:41:03.330494852 +0800 CST m=+80.653959932, ka.deadline:2018-07-05 22:41:43.330496602 +0800 CST m=+120.653961489 2018/07/05 22:41:03 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:41:03 karesp.TTL:60, nextKeepAlive:2018-07-05 22:41:23.341112484 +0800 CST m=+100.664577164,ka.nextKeepAlive:2018-07-05 22:41:23.341112484 +0800 CST m=+100.664577164, ka.deadline:2018-07-05 22:42:03.341113662 +0800 CST m=+140.664578212 2018/07/05 22:41:23 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:41:23 karesp.TTL:60, nextKeepAlive:2018-07-05 22:41:43.350264635 +0800 CST m=+120.673729313,ka.nextKeepAlive:2018-07-05 22:41:43.350264635 +0800 CST m=+120.673729313, ka.deadline:2018-07-05 22:42:23.350265498 +0800 CST m=+160.673730050 2018/07/05 22:41:43 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:41:43 karesp.TTL:60, nextKeepAlive:2018-07-05 22:42:03.572888276 +0800 CST m=+140.896353032,ka.nextKeepAlive:2018-07-05 22:42:03.572888276 +0800 CST m=+140.896353032, ka.deadline:2018-07-05 22:42:43.572889271 +0800 CST m=+180.896353840 2018/07/05 22:42:03 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:42:03 karesp.TTL:60, nextKeepAlive:2018-07-05 22:42:23.86879775 +0800 CST m=+161.192262488,ka.nextKeepAlive:2018-07-05 22:42:23.86879775 +0800 CST m=+161.192262488, ka.deadline:2018-07-05 22:43:03.868798687 +0800 CST m=+201.192263243 2018/07/05 22:42:23 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:42:23 karesp.TTL:60, nextKeepAlive:2018-07-05 22:42:43.877613966 +0800 CST m=+181.201079020,ka.nextKeepAlive:2018-07-05 22:42:43.877613966 +0800 CST m=+181.201079020, ka.deadline:2018-07-05 22:43:23.877615637 +0800 CST m=+221.201080417 2018/07/05 22:42:43 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:42:43 karesp.TTL:60, nextKeepAlive:2018-07-05 22:43:03.884576518 +0800 CST m=+201.208041122,ka.nextKeepAlive:2018-07-05 22:43:03.884576518 +0800 CST m=+201.208041122, ka.deadline:2018-07-05 22:43:43.884577361 +0800 CST m=+241.208041904 2018/07/05 22:43:03 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:43:03 karesp.TTL:60, nextKeepAlive:2018-07-05 22:43:23.893274193 +0800 CST m=+221.216738996,ka.nextKeepAlive:2018-07-05 22:43:23.893274193 +0800 CST m=+221.216738996, ka.deadline:2018-07-05 22:44:03.893275148 +0800 CST m=+261.216739702 2018/07/05 22:43:23 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:43:24 karesp.TTL:60, nextKeepAlive:2018-07-05 22:43:44.058766258 +0800 CST m=+241.382230998,ka.nextKeepAlive:2018-07-05 22:43:44.058766258 +0800 CST m=+241.382230998, ka.deadline:2018-07-05 22:44:24.058767168 +0800 CST m=+281.382231711 2018/07/05 22:43:44 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:43:44 karesp.TTL:60, nextKeepAlive:2018-07-05 22:44:04.413012991 +0800 CST m=+261.736477737,ka.nextKeepAlive:2018-07-05 22:44:04.413012991 +0800 CST m=+261.736477737, ka.deadline:2018-07-05 22:44:44.41301386 +0800 CST m=+301.736478391 2018/07/05 22:44:04 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:44:04 karesp.TTL:60, nextKeepAlive:2018-07-05 22:44:24.420796492 +0800 CST m=+281.744261106,ka.nextKeepAlive:2018-07-05 22:44:24.420796492 +0800 CST m=+281.744261106, ka.deadline:2018-07-05 22:45:04.420797607 +0800 CST m=+321.744262161 2018/07/05 22:44:24 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:44:24 karesp.TTL:60, nextKeepAlive:2018-07-05 22:44:44.428145652 +0800 CST m=+301.751610589,ka.nextKeepAlive:2018-07-05 22:44:44.428145652 +0800 CST m=+301.751610589, ka.deadline:2018-07-05 22:45:24.428147239 +0800 CST m=+341.751612018 2018/07/05 22:44:44 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:44:44 karesp.TTL:60, nextKeepAlive:2018-07-05 22:45:04.436151288 +0800 CST m=+321.759615961,ka.nextKeepAlive:2018-07-05 22:45:04.436151288 +0800 CST m=+321.759615961, ka.deadline:2018-07-05 22:45:44.436152168 +0800 CST m=+361.759616723 2018/07/05 22:45:04 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:45:04 无法写入 2018/07/05 22:45:04 karesp.TTL:60, nextKeepAlive:2018-07-05 22:45:24.441563525 +0800 CST m=+341.765028110,ka.nextKeepAlive:2018-07-05 22:45:04.436151288 +0800 CST m=+321.759615961, ka.deadline:2018-07-05 22:46:04.44156426 +0800 CST m=+381.765028789 2018/07/05 22:45:04 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:45:04 无法写入 2018/07/05 22:45:04 karesp.TTL:60, nextKeepAlive:2018-07-05 22:45:24.941897369 +0800 CST m=+342.265361977,ka.nextKeepAlive:2018-07-05 22:45:04.436151288 +0800 CST m=+321.759615961, ka.deadline:2018-07-05 22:46:04.941898136 +0800 CST m=+382.265362694 2018/07/05 22:45:05 lease Id KeepAliveRequest:5904610818195269641 2018/07/05 22:45:05 无法写入再16次之后，即第17次，开始恢复每秒2次的租约请求。。。所以，也验证了此 bug。也就是说不管grant的租约TTL设置多久，最终都会变成0.5秒发送lease 续期一次！！！！！也就是说不管grant的租约TTL设置多久，最终都会变成0.5秒发送lease 续期一次！！！！！也就是说不管grant的租约TTL设置多久，最终都会变成0.5秒发送lease 续期一次！！！！！之前的134版本灰度灰度后，中间CPU 降低了大约1个小时的样子，这是为什么呢？解释 cpu 降低1小时的疑点：我们这么计算， TTL 600，续约续约是200， ka.chs的数组长度是1，第一个chan <- LeasesKeepAliveResponse的长度是16 ，全部写满的时间是20016/60 = 53分钟。也非常契合 falcon 上的 cpu 信息截图另外再从我加日志的第一次测试时间来算： 2018/07/05 22:04:05 - 2018/07/05 21:10:42 约为53分钟。也就是说，将近1小时，跟 falcon 的统计吻合的。。。找到真凶：定问题了，就是修复方式了，我并没看到 ch channel 的使用的地方，或许我没理解作者的用意，我觉得，不管 ch channel 是否写入，都必须将下一次nextKeepAlive的时间赋值为最新时间。将ka.nextKeepAlive = nextKeepAlive移到for select外面即可。不过，我们产品急于推广，保险起见，牺牲了 lease 的需求，去掉了这个功能。发布到服务器后，负载情况有非常大的改善，CPU 从40%-50%降低到2%-5%左右。回顾总结：回顾etcd 集群遇到的所有现象，配合这个问题，所有问题都好解释了，那么，我按照事情发生发展的顺序总结一下原因： etcd clientv3的lease keepalive 类库有 bug，不管 ttl 设置多久，都会在续期16次后，变为0.5s 一次 agent 部署到大量服务器上后（2W 台），每个 agent 持有一个 lease id agent（相对于 etcd 来说，是client）连接到 etcd member 上，将lease 续期请求每秒2次发送到 member 上 etcd member 跟 leader 在续期 lease 上是使用 http 1.1，TCP 连接在上一个请求没响应之前，没法复用，几乎都是新创建的 TCP 连接 etcd leader 节点每秒收到 2W * 2 个 TCP 连接请求早期 etcd node 之间是 https 通讯，TCP 建立后，会进行 TLS 握手，TLS 校验是 RSA 的数学计算，会消耗大量 CPU，导致 leader 节点 CPU 飙升 etcd leader 使用 grpc 类库监听的 http server，每一个 client 连接过来时，都会创建对象、结构体、channel用来通讯，占用更多内存 etcd leader 收到 etcd member转发来的 lease keepalive请求，放到一个slice里（实际上这块是grpc做的） etcd leader 对存放recvMsg的b.backlog 写入速度大于消费速度，导致 slice 越来越大，占用更多内存，导致内存不停上升，导致内存溢出假象 etcd leader 处理请求的速度小于写入速度，导致请求堆积，超过 lease id 的 TTL，导致 lease id 判断过期，删除 TTL，也解释了 hids server 的 key 莫名其妙消失的现象 etcd member 大量新建 TCP 请求到 etcd leader，leader 处理后就关闭连接，导致 leader 侧会出现大量 TIME-WAIT 状态的链接。 etcd leader 处理 member lease 的请求太慢，超过 TLS 的10s 后，member 触发 TLS 超时，主动断开连接，但 leader 仍处理不过来，TCP 连接变为 CLOSE-WAIT 状态最终，稻草压死骆驼。该 bug 已反馈至 etcd 官方 clientv3 sdk will send /etcdserverpb.Lease/LeaseKeepAlive twice every second for lease id after over time 困扰我1个多月的 bug，不会忘记这个时刻关于 etcd 过载保护的想法： etcd lease 的 keepalive 放到2/3的时间点去做是不是更合适？ grpc 的过载保护是不是也要做下，比如接受 client 请求这里从数组改用定长队列，超过丢弃，来保证集群可用。 etcd 节点之间通讯改用 http2是不是更合适声明本文可转载，但不得删除文中招聘信息，以及QQ 群信息。原文来自：www.cnxct.com/etcd-lease-keepalive-debug-note/ 招聘[上海/北京]安全研发专家月薪 40k-60k 上海市／ 5-10 年／本科／研发招聘[上海/北京]美团点评--50-80K 招 Java 高级技术专家简历请发至 cfc4n[{at}]cnxct.com ，谢谢。对你的etcd 产品是否影响：使用etcd clientv3(golang 的客户端类库) ，所有v3版本的客户端（包括3.0.x，3.1.x，3.2.x，3.3.x，3.4.x）。使用 lease 租约，并设置 keepalive client 量比较大能看出来效果，几百台的话，对性能影响不大。官方已修复 coreos etcd在2018年7月24日已经修复该 bug，涉及etcd client v3的3个版本效率非常高。详情如下 https://github.com/coreos/etcd/blob/master/CHANGELOG-3.1.md https://github.com/coreos/etcd/blob/master/CHANGELOG-3.2.md https://github.com/coreos/etcd/blob/master/CHANGELOG-3.3.md Fix lease keepalive interval updates when response queue is full. If <-chan *clientv3LeaseKeepAliveResponse from clientv3.Lease.KeepAlive was never consumed or channel is full, client was sending keepalive request every 500ms instead of expected rate of every "TTL / 3" duration.