记录一个__lll_lock_wait_private错误

一个DBA同事昨天在执行一个命令行工具的时候发现程序hang住，问题挺有意思，值得记录下。

首先用pstack看了下程序的调用栈，这是个多线程程序，pstack结果看到几乎所有的线程都等在write调用上。如下是pt-pmp的输出结果：

Tue May 27 18:30:06 CST 2014 55 __lll_lock_wait_private,_L_lock_51,fwrite,LoadConsumer::run,CThread::hook,start_thread,clone1 write,_IO_new_file_write,_IO_new_file_xsputn,buffered_vfprintf,vfprintf,fprintf,LoadManager::dump,LoadProducer::load_file,LoadProducer::run,CThread::hook,start_thread,clone

直觉上觉得是磁盘空间满了，让他看了下，磁盘空间还很富裕，touch创建文件也没任何问题，当时此机器上还在跑一个备份程序，IO压力不小，不过和问题本身应该关系不大。Google了下__lll_lock_wait_private这个错误，也没任何有用的信息。这个工具程序本身会向一个命令行指定的日志文件输出很多程序执行结果，同时会向stderr输出程序的执行状态，gdb attach看了下程序具体的调用栈，发现程序都阻塞在fprintf(stderr)上。咨询了下同事，他使用这个工具是通过一个python脚本调用的，调用的程序类似如下：

p = subprocess.Popen(cmd,shell=True,stdout=subprocess.PIPE,stderr=subprocess.STDOUT,close_fds=True)

cmd是调用程序的命令行，包括一系列选项。问题看起来很清晰了，通过python调用此命令行工具时，stdout和stderr都被重定向了subprocess.PIPE，但没有程序从此PIPE读取，那么很快这个PIPE自身的buffer都写满了，pstack看到的结果就是所有write都阻塞。

写了个小程序重现了下，程序如下（随手写的..）:

1 #include 2 #include 3 #include 4 void *thr_fn(void *arg)5 {6 int i =0;7 while(true)8 {9 i++; 10 fprintf(stderr, "helloworld %d/t/t/t/t",i); 11 fprintf(stdout, "kkkkkkkkkk %d/t/t/t/t",i); 12 sleep(1); 13 } 14 } 15 16 int main(void) 17 { 18 for (int i = 0; i!= 50; i++) 19 { 20 pthread_t tid; 21 pthread_create(&tid, NULL, thr_fn, NULL); 22 } 23 24 sleep(100000); 25 }

调用的python脚本如下：

1 import subprocess2 import os3 import time45 ret = {}67 cmd = "./a.out >/tmp/log"89 p = subprocess.Popen(cmd,shell=True,stdout=subprocess.PIPE,stderr=subprocess.STDOUT,close_fds=True) 10 11 ret['status'] = p.wait() 12 ret['msg'] = p.stdout.readlines() 13 14 time.sleep(100000000);

执行此python脚本，会发现很快a.out就被hang住了，表现是/tmp/log不再有新的输出，程序调用栈如下：

49 __lll_lock_wait_private,_L_lock_12956,buffered_vfprintf,vfprintf,fprintf,thr_fn,start_thread,clone1 write,_IO_new_file_write,_IO_new_file_xsputn,buffered_vfprintf,vfprintf,fprintf,thr_fn,start_thread,clone1 nanosleep,sleep,main

解决此问题，1）maybe subprocess.Popen这个程序参数可以改改？2）或者在cmd里边将stdout/stderr都重定向掉；3）写命令行程序的时候要注意，调用的脚本各种写法都可能有，因此写日志尽量还是要规范，不要向stdout/stderr输出过多的东西。

组里开发的同事补充了下MySQL遇到__lll_lock_wait_private 错误的常见场景：

"这个函数调用在mysql上最典型的场景就是开启cgroup时会经常碰到这个，例如memcpy, mem alloc, free , mutext lock/unlock...."