记录一个__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,clone
      1 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 <stdio.h>
  2 #include <pthread.h>
  3 #include <unistd.h>
  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 subprocess
  2 import os
  3 import time
  4
  5 ret = {}
  6
  7 cmd = "./a.out >/tmp/log"
  8
  9 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,clone
      1 write,_IO_new_file_write,_IO_new_file_xsputn,buffered_vfprintf,vfprintf,fprintf,thr_fn,start_thread,clone
      1 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...."