記錄一個__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...."