天翼云代理,天翼云代理商,北京代理商
天翼云折扣专线：400-150-1900（全国市话）
图文教程

【线上故障】通过系统日志分析和定位

图文教程
2022-02-22 03:29:43

在之前的文章中，咱们有讲到如何定位内存走漏和GDB调试-从入门实践到原理。今日，凭借本文，来分享别的一种更为扎手的线上问题处理方案-如安在没有coredump文件的状况下，定位程序溃散原因。

前语

一个优异的程序员，编码才能和处理问题的才能必不可少。编码才能表现的是逻辑思维才能，而处理问题的才能不仅仅依靠自己经历的积累，更需要必定的敏锐嗅觉和运用其他方法处理问题的才能。管他黑猫白猫，抓住老鼠便是好猫。

在日常的项目开发中，依据Bug发生的时机和环境，咱们能够将Bug细分为以下几种：

  • 线下缺点：此阶段发生在上线前。主要在测验阶段，由开发人员在自测过程中或者有测验人员发现
  • 线上问题：此阶段发生在上线后，也便是在正式环境或者生产环境。主要是不符合产品的需求逻辑，或许会影响用户体会
  • 线上毛病：这个阶段是最严峻的，对公司的收益、用户体会都会造成影响，主要为服务不可用等

在本文的示例中，咱们针对的第三个阶段，即线上毛病进行定位和剖析的一种方法，期望凭借本文，能够对你的毛病定位才能有必定的帮助。

背景

早上到了公司，正在愉快地摸鱼，忽然企业微信来了条报警，某个中心服务从头启动了。

所以，快速翻开iterm，经过跳板机登录线上服务器，榜首时间，检查有没有coredump文件生成:

仿制 
ll /www/coredump/ total 0 
							
    
								
								
  • 
									1.
								
    • 

								
  • 
									2.
								
    •

竟然没有coredump文件，其时心境是这样的：

其时榜首反应是有人手动重启了，所以在组内群里问了下，没人动线上，看来问题比较麻烦。

排查

既然没有coredump文件发生，且没有人手动重启服务，只能剖析下系统日志，看看能得到什么线索。

经过在系统日志中，查找进程名来获取进程发生错误时分的日志信息。

仿制 
grep xxx /var/log/messages

kernel: xxx[11120]: segfault at 7f855009e49f ip 0000003ab9a75f62 sp 00007fcccd7f74c0 error 4 in libc-2.12.so[3ab9a00000+18b000] 
								
    
									
									
  • 
										1.
									
    • 

									
  • 
										2.
									
    • 

									
  • 
										3.
									
    •

在上面的信息中：

  • xxx 为进程名，后边括号中的11120代表其时的线程id7f855009e49f为出错时分的地址
  • 0000003ab9a75f62为发生错误时指令的地址
  • 00007fcccd7f74c0 为仓库指针
  • 3ab9a00000为libc在此程序中映射的内存基址
  • segfault at和error 4这两条信息能够得出是内存读出错

其中，内核对error的界说如下：

仿制 
/*  * Page fault error code bits:  *  *   bit 0 ==  0: no page found 1: protection fault  *   bit 1 ==  0: read access  1: write access  *   bit 2 ==  0: kernel-mode access 1: user-mode access  *   bit 3 ==    1: use of reserved bit detected  *   bit 4 ==    1: fault was an instruction fetch  *   bit 5 ==    1: protection keys block access  */ enum x86_pf_error_code { X86_PF_PROT = 1 << 0, X86_PF_WRITE = 1 << 1, X86_PF_USER = 1 << 2, X86_PF_RSVD = 1 << 3, X86_PF_INSTR = 1 << 4, X86_PF_PK = 1 << 5, }; #endif /* _ASM_X86_TRAPS_H */ 
				
    
					
					
  • 
						1.
					
    • 

					
  • 
						2.
					
    • 

					
  • 
						3.
					
    • 

					
  • 
						4.
					
    • 

					
  • 
						5.
					
    • 

					
  • 
						6.
					
    • 

					
  • 
						7.
					
    • 

					
  • 
						8.
					
    • 

					
  • 
						9.
					
    • 

					
  • 
						10.
					
    • 

					
  • 
						11.
					
    • 

					
  • 
						12.
					
    • 

					
  • 
						13.
					
    • 

					
  • 
						14.
					
    • 

					
  • 
						15.
					
    • 

					
  • 
						16.
					
    • 

					
  • 
						17.
					
    • 

					
  • 
						18.
					
    • 

					
  • 
						19.
					
    •

error 4代表用户态程序内存拜访越界。

好了，经过上述内核日志，咱们根本能够得出如下定论：

名为xxx的进程中，线程id为11120发生了用户态程序内存拜访越界，且最终core在了libc-2.12.so中。原因根本确定，现在咱们开端定位问题。

开始定位

运用ldd指令，检查可执行程序的依靠：

仿制 
ldd xxx
 linux-vdso.so.1 => (0x00007ffedb331000) librt.so.1 => /lib64/librt.so.1 (0x0000003aba200000) libdl.so.2 => /lib64/libdl.so.2 (0x0000003ab9600000) libstdc++.so.6 => /usr/lib64/libstdc++.so.6 (0x0000003abce00000) libm.so.6 => /lib64/libm.so.6 (0x0000003aba600000) libc.so.6 => /lib64/libc.so.6 (0x0000003ab9a00000) /lib64/ld-linux-x86-64.so.2 (0x0000562e90634000) libpthread.so.0 => /lib64/libpthread.so.0 (0x0000003ab9e00000) libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x0000003abc200000) 
					
    
						
						
  • 
							1.
						
    • 

						
  • 
							2.
						
    • 

						
  • 
							3.
						
    • 

						
  • 
							4.
						
    • 

						
  • 
							5.
						
    • 

						
  • 
							6.
						
    • 

						
  • 
							7.
						
    • 

						
  • 
							8.
						
    • 

						
  • 
							9.
						
    • 

						
  • 
							10.
						
    •

在上一节中，咱们得到了程序发生错误时指令的地址(0000003ab9a75f62)以及libc-2.12.so在进程中的基址(3ab9a00000)，下面我经过objdump指令来进行剖析。

反汇编

经过下述指令，得到libc-2.12.so汇编结果(由于内容较多，咱们将其重定向输出到一个临时文件)

仿制 
objdump -tT /lib64/libc-2.12.so > ~/info
				
    
					
					
  • 
						1.
					
    •

查找汇编句子

Libc-2.21.so是个基础库，其内容多达58m，很难直接从中获取有用信息。

仿制 
ll info -rw-r--r-- 1 root root 58369282 Jan 28 10:14 info 
						
    
							
							
  • 
								1.
							
    • 

							
  • 
								2.
							
    •

为了快速定位错误点，咱们抓取跟错误点地址3ab9a75f62相关的指令(为了获取上下文，所以grep了部分)

仿制 
objdump -tT /lib64/libc-2.12.so | grep 3ab9a75
								
    
									
									
  • 
										1.
									
    •

输出如下：

仿制 
0000003ab9a75100 l     F .text 0000000000000176 enlarge_userbuf 0000003ab9a756b0 l     F .text 000000000000011b              ptmalloc_lock_all 0000003ab9a757d0 l     F .text 00000000000000b6              ptmalloc_unlock_all 0000003ab9a75890 l     F .text 00000000000000c1              ptmalloc_unlock_all2 0000003ab9a75960 l     F .text 0000000000000003 __failing_morecore 0000003ab9a75a20 l     F .text 00000000000000da              sYSTRIm 0000003ab9a75b00 l     F .text 000000000000029d              mem2chunk_check 0000003ab9a75da0 l     F .text 00000000000000e0 malloc_printerr 0000003ab9a75e80 l     F .text 0000000000000541 malloc_consolidate 0000003ab9a75280 l     F .text 0000000000000187 _IO_str_seekoff_internal 0000003ab9a75970 l     F .text 000000000000006b              __malloc_check_init 0000003ab9a75410 l     F .text 00000000000001aa              _IO_str_overflow_internal 0000003ab9a759e0 l     F .text 0000000000000031 __malloc_usable_size 0000003ab9a75020 l     F .text 0000000000000062 _IO_str_underflow_internal 0000003ab9a750b0 l     F .text 000000000000002b              _IO_str_finish 0000003ab9a75090 l     F .text 0000000000000012 _IO_str_count 0000003ab9a755c0 l     F .text 00000000000000ae              _IO_str_init_static_internal 0000003ab9a750e0 l     F .text 0000000000000015 _IO_str_pbackfail_internal 0000003ab9a759e0  w    F .text 0000000000000031 malloc_usable_size 0000003ab9a75020 g     F .text 0000000000000062 _IO_str_underflow 0000003ab9a750e0 g     F .text 0000000000000015 _IO_str_pbackfail 0000003ab9a75410 g     F .text 00000000000001aa              _IO_str_overflow 0000003ab9a75670 g     F .text 000000000000001d              _IO_str_init_readonly 0000003ab9a75690 g     F .text 0000000000000012 _IO_str_init_static 0000003ab9a75280 g     F .text 0000000000000187 _IO_str_seekoff 0000003ab9a750e0 g    DF .text 0000000000000015 GLIBC_2.2.5 _IO_str_pbackfail 0000003ab9a75690 g    DF .text 0000000000000012 GLIBC_2.2.5 _IO_str_init_static 0000003ab9a759e0  w   DF .text 0000000000000031 GLIBC_2.2.5 malloc_usable_size 0000003ab9a75020 g    DF .text 0000000000000062 GLIBC_2.2.5 _IO_str_underflow 0000003ab9a75280 g    DF .text 0000000000000187 GLIBC_2.2.5 _IO_str_seekoff 0000003ab9a75410 g    DF .text 00000000000001aa  GLIBC_2.2.5 _IO_str_overflow 0000003ab9a75670 g    DF .text 000000000000001d  GLIBC_2.2.5 _IO_str_init_readonly
										
    
											
											
  • 
												1.
											
    • 

											
  • 
												2.
											
    • 

											
  • 
												3.
											
    • 

											
  • 
												4.
											
    • 

											
  • 
												5.
											
    • 

											
  • 
												6.
											
    • 

											
  • 
												7.
											
    • 

											
  • 
												8.
											
    • 

											
  • 
												9.
											
    • 

											
  • 
												10.
											
    • 

											
  • 
												11.
											
    • 

											
  • 
												12.
											
    • 

											
  • 
												13.
											
    • 

											
  • 
												14.
											
    • 

											
  • 
												15.
											
    • 

											
  • 
												16.
											
    • 

											
  • 
												17.
											
    • 

											
  • 
												18.
											
    • 

											
  • 
												19.
											
    • 

											
  • 
												20.
											
    • 

											
  • 
												21.
											
    • 

											
  • 
												22.
											
    • 

											
  • 
												23.
											
    • 

											
  • 
												24.
											
    • 

											
  • 
												25.
											
    • 

											
  • 
												26.
											
    • 

											
  • 
												27.
											
    • 

											
  • 
												28.
											
    • 

											
  • 
												29.
											
    • 

											
  • 
												30.
											
    • 

											
  • 
												31.
											
    • 

											
  • 
												32.
											
    •

为了进一步定位问题点，咱们运用objdump指令并指定起始点

仿制 
objdump -d /lib64/libc-2.12.so --start-address=0x3ab9a75000 | head -n2000 | grep 75f62 
												
    
													
													
  • 
														1.
													
    •

输出如下：

仿制 
3ab9a75ec8: 0f 85 94 00 00 00 jne 3ab9a75f62 <malloc_consolidate+0xe2> 3ab9a75f62: 48 8b 43 08 mov 0x8(%rbx),%rax
														
    
															
															
  • 
																1.
															
    • 

															
  • 
																2.
															
    •

根本能够确定在进行malloc的时分，出现了问题。

精准定位在上节中，咱们定位到原因是malloc导致，可是代码量太大，任何一个对象底层都有或许调用了malloc(new也会调用malloc)，所以一时半会，不知道从哪下手。

为了定位原因，选用最近定位法，剖析最近一次上线的代码改动，这次改动，将之前的redis Sentinel改为了redis cluster，而redis 官方没有提供cluster的client，所以自己手撸了个client，而在这个client中调用malloc次序如下：

仿制 
-> Init --> redisClusterInit ----> calloc ------> malloc 
																
    
																	
																	
  • 
																		1.
																	
    • 

																	
  • 
																		2.
																	
    • 

																	
  • 
																		3.
																	
    • 

																	
  • 
																		4.
																	
    •

好了，到此，进程溃散的代码点根本定位了，下面我进行原因剖析。

原因剖析

程序对RedisClusterClient进行初始化的当地有两个：

  • 程序启动的时分
  • 当连接断开的时分

由于程序现已运行了一段时间，所以榜首条根本不成立，那么咱们看下本次改动运用的指令之一ZRangeByScore的实现：

仿制 
void RedisClusterClient::ZRangeByScore(std::string& key, std::string min, std::string max, std::vector<std::string> *vals, bool withscores, std::string *msg) { // ....
  redisReply *reply = static_cast<redisReply*>( redisClusterCommandArgv(cc_, argv.size(), &(argv[0]), &(argvlen[0]))); if (!reply || reply->type != REDIS_REPLY_ARRAY) { // ...
      redisClusterFree(cc_); cc_ = nullptr; Init(host_, password_, &connect_timeout_, &op_timeout_, msg); } return; } // ... } 
																			
    
																				
																				
  • 
																					1.
																				
    • 

																				
  • 
																					2.
																				
    • 

																				
  • 
																					3.
																				
    • 

																				
  • 
																					4.
																				
    • 

																				
  • 
																					5.
																				
    • 

																				
  • 
																					6.
																				
    • 

																				
  • 
																					7.
																				
    • 

																				
  • 
																					8.
																				
    • 

																				
  • 
																					9.
																				
    • 

																				
  • 
																					10.
																				
    • 

																				
  • 
																					11.
																				
    • 

																				
  • 
																					12.
																				
    • 

																				
  • 
																					13.
																				
    • 

																				
  • 
																					14.
																				
    • 

																				
  • 
																					15.
																				
    • 

																				
  • 
																					16.
																				
    • 

																				
  • 
																					17.
																				
    • 

																				
  • 
																					18.
																				
    • 

																				
  • 
																					19.
																				
    •

单纯这块代码，是不会有问题的，所以需要把运用这块代码的都考虑进来。咱们从头理下请求的调用链：

仿制 
-> Load --> GetHandler ----> GetSession ------> GetRedisClient 
																					
    
																						
																						
  • 
																							1.
																						
    • 

																						
  • 
																							2.
																						
    • 

																						
  • 
																							3.
																						
    • 

																						
  • 
																							4.
																						
    •

从头进行代码剖析，发现在特定条件下，GetRedisClient或许会被多个线程一起调用，假如不进行Init的话，一切正常，而当一个线程Init的时分，恰好别的一个线程进行读，因而引起了拜访一个现已释放的内存地址，所以导致了进程溃散。

这种状况发生的概率很低，很难重现。毕竟连接忽然断开的一起，又有一个线程在一起拜访，在线上仍是很难出现(当然能够在线下经过tcpkill进行模仿，这便是别的一回事了)，整体来说，仍是比较幸运，能够迅速定位。

问题处理

在整个bug的剖析和处理过程中，定位segfault是最困难的当地，假如知道了segfault的当地，剖析原因，就相对来说简单多了。当然，知道了溃散原因，处理就更不在话下了

12年经验 · 提供上云保障

服务热线：132-6161-6125（手机） 400-150-1900（全国市话）

站内导航： 天翼云服务器价格| 天翼云购买流程| 天翼云代理| 北京天翼云代理商| 杭州天翼云代理| 深圳天翼云代理商| 钉钉代理商| 阿里云代理| 公司官网

我公司收款账号| 天翼云备案系统

CopyRight © 2019 天翼云代理商. All Rights Reserved　京ICP备11011846号-15　管理-北京志远天辰科技有限公司