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