Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード Twitter

2015-02-13

VirtualBox を 4.3.20 から 4.3.22 にアップグレードした

手順は VirtualBox を 4.3.16 から 4.3.20 にアップグレードしたメモ - ablog と同じ。

[root@yazekats-linux ~]# yum update VirtualBox-4.3
(中略)
================================================================================
 Package             Arch        Version                  Repository       Size
================================================================================
Updating:
 VirtualBox-4.3      x86_64      4.3.22_98236_el6-1       virtualbox       68 M

Transaction Summary
================================================================================
Upgrade       1 Package(s)

Total download size: 68 M
Is this ok [y/N]: y
Downloading Packages:
VirtualBox-4.3-4.3.22_98236_el6-1.x86_64.rpm             |  68 MB     02:56     
Running rpm_check_debug
Running Transaction Test
Transaction Test Succeeded
Running Transaction
  Updating   : VirtualBox-4.3-4.3.22_98236_el6-1.x86_64                     1/2 

Creating group 'vboxusers'. VM users must be member of that group!

No precompiled module for this kernel found -- trying to build one. Messages
emitted during module compilation will be logged to /var/log/vbox-install.log.

Stopping VirtualBox kernel modules [  OK  ]
Uninstalling old VirtualBox DKMS kernel modules [  OK  ]
Trying to register the VirtualBox kernel modules using DKMS [  OK  ]
Starting VirtualBox kernel modules [  OK  ]
  Cleanup    : VirtualBox-4.3-4.3.20_96996_el6-1.x86_64                                                                                                            2/2 
  Verifying  : VirtualBox-4.3-4.3.22_98236_el6-1.x86_64                                                                                                            1/2 
  Verifying  : VirtualBox-4.3-4.3.20_96996_el6-1.x86_64                                                                                                            2/2 

Updated:
  VirtualBox-4.3.x86_64 0:4.3.22_98236_el6-1                                                                                                                           

Complete!

いつもより時間がかかるので、pstree で見てみるといろいろやってるみたい、

$ ps auxw|grep yum|grep -v grep
root      4774 11.9  0.9 446356 148708 pts/0   S+   10:17   2:05 /usr/bin/python /usr/bin/yum update VirtualBox-4.3
$ watch pstree -alp 4774
yum,4774 /usr/bin/yum update VirtualBox-4.3
  └─sh,5134 /var/tmp/rpm-tmp.3nXBqe 2
      └─vboxdrv,5299 /etc/init.d/vboxdrv setup
          └─do_dkms,5322 /usr/share/virtualbox/src/vboxhost/do_dkms uninstall vboxhost vboxdrv vboxnetflt vboxnetadp
              └─do_dkms,5326 /usr/share/virtualbox/src/vboxhost/do_dkms uninstall vboxhost vboxdrv vboxnetflt vboxnetadp
                  └─dkms,5567 /usr/sbin/dkms remove -m vboxhost -v 4.3.20 --all
                      └─weak-modules,5791 /sbin/weak-modules --remove-modules
                          └─dracut,19128 /sbin/dracut -f /boot/initramfs-3.8.13-26.1.1.el6uek.x86_64.tmp 3.8.13-26.1.1.el6uek.x86_64
                              └─dracut,4739 /sbin/dracut -f /boot/initramfs-3.8.13-26.1.1.el6uek.x86_64.tmp 3.8.13-26.1.1.el6uek.x86_64
                                  ├─cpio,4746 -R 0:0 -H newc -o --quiet
                                  └─gzip,4747 -9

追記:

4.3.20 の時はゲストの Windows 7EXCEL を使っているとよくブルースクリーンになったが、4.3.22 で今のところ安定動作している。

2015-01-24

is not null で count する SQL を Index Only "Fast Full" Scan で高速化する

is not null で count する SQL を Index Only "Fast Full" Scan で仕事(計算)量を減らして高速化してみた。インデックスを作成すると、オプティマイザが期待していた仕事(計算)量が少なくなる実行計画を選択してくれた。


チューニング結果

ビフォー
17:36:30 SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.88
17:36:51 SQL> select count(c2) from test1 where c5 is not null;

 COUNT(C2)
----------
    100000

Elapsed: 00:00:05.70
17:37:11 SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID	6wksv9bxncxa5, child number 0
-------------------------------------
select count(c2) from test1 where c5 is not null

Plan hash value: 3896847026

-----------------------------------------------------------------------------------------------
| Id  | Operation	   | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |	   |	  1 |	     |	    1 |00:00:05.65 |	5057 |	 5053 |
|   1 |  SORT AGGREGATE    |	   |	  1 |	   1 |	    1 |00:00:05.65 |	5057 |	 5053 |
|*  2 |   TABLE ACCESS FULL| TEST1 |	  1 |  21065 |	  100K|00:00:05.57 |	5057 |	 5053 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("C5" IS NOT NULL)


19 rows selected.

Elapsed: 00:00:00.51
アフター
17:37:25 SQL> create index idx_test1 on test1(c2,c5);

Index created.

Elapsed: 00:00:43.33
17:45:46 SQL> alter system flush buffer_cache;

System altered.

Elapsed: 00:00:00.26
17:46:04 SQL> select count(c2) from test1 where c5 is not null;

 COUNT(C2)
----------
    100000

Elapsed: 00:00:00.66
17:46:14 SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID	6wksv9bxncxa5, child number 2
-------------------------------------
select count(c2) from test1 where c5 is not null

Plan hash value: 2671621383

------------------------------------------------------------------------------------------------------
| Id  | Operation	      | Name	  | Starts | E-Rows | A-Rows |	 A-Time   | Buffers | Reads  |
------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      | 	  |	 1 |	    |	   1 |00:00:00.66 |    1032 |	1025 |
|   1 |  SORT AGGREGATE       | 	  |	 1 |	  1 |	   1 |00:00:00.66 |    1032 |	1025 |
|*  2 |   INDEX FAST FULL SCAN| IDX_TEST1 |	 1 |  21065 |	 100K|00:00:00.58 |    1032 |	1025 |
------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("C5" IS NOT NULL)


19 rows selected.

Elapsed: 00:00:00.32

準備手順

export LANG=C
export NLS_LANG=American_America.AL32UTF8
sqlplus /nolog
conn scott/tiger
set time on
set timing on
set pagesize 50000
set linesize 200

create table test1(c1 number, c2 char(30), c3 char(30), c4 char(30), c5 char(30));

begin
    for i in 1..1000000 loop
        insert into test1(c1, c2,c3,c4,c5) values(i,null,null,null,null);
    end loop;
end;
/
commit;

begin
for i in 100001..200000 loop
insert into test1(c1, c2,c3,c4,c5) values(i,i,i,i,i);
end loop;
end;
/
commit;

alter session set statistics_level=all;

環境

SQL> select * from V$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
PL/SQL Release 11.2.0.4.0 - Production
CORE	11.2.0.4.0	Production
TNS for Linux: Version 11.2.0.4.0 - Production
NLSRTL Version 11.2.0.4.0 - Production

最近使った Perl ワンライナーのメモ

perl -lane '$F[2]=~s/^([a-z]+).*/$1/; $h->{$F[1]}->{$F[2]}++;END{map{$t=$_ and print $t;map{print qq/$t\t$_\t$h->{$t}->{$_}/} keys %{$h->{$_}}} keys %$h}'' strace.log
grep -hA 20 '^top -' top.logperl -lane '/top - ([\d:]+)/ and $t=$1;$F[0]=~/\d+/ and printf (qq/%s %s%s\n/,$t,$_,lc(sprintf(q/%X/,$F[0])))'

chrome を 更新した

[root@yazekats-linux ~]# yum update google-chrome-stable

...

Updated:
  google-chrome-stable.x86_64 0:40.0.2214.91-1                                  

Complete!

[root@yazekats-linux ~]# cat /etc/issue
Oracle Linux Server release 6.4
Kernel \r on an \m

[root@yazekats-linux ~]# uname -r
2.6.39-400.17.1.el6uek.x86_64

"commit" and "log file sync"

When you commit a transaction you update the transaction table slot that identifies your transaction to show that the transaction is committed – this is a change to an undo segment header block so it generates a redo change vector. THe handling of this vector is completely standard – your session creates a redo record from it and puts the record into the log buffer – which means it is applied to the undo block at that moment, which means everyone can now see the effects of your transaction. AFTER the record is in the redo buffer your session will post lgwr to write the log buffer to the log file and goes into a “log file sync” wait. But this means (a) your transaction is visible to everyone else before it is recoverable (durable) and (b) you’re the only session that thinks the transaction hasn’t yet “really committed”.

Redo | Oracle Scratchpad

参考

2015-01-21

strace で出力される resumed の意味

If a system call is being executed and meanwhile another one is being

called from a different thread/process then strace will try to

preserve the order of those events and mark the ongoing call as being

unfinished. When the call returns it will be marked as resumed.

[pid 28772] select(4, [3], NULL, NULL, NULL <unfinished ...>

[pid 28779] clock_gettime(CLOCK_REALTIME, {1130322148, 939977000}) = 0

[pid 28772] <... select resumed> ) = 1 (in [3])

strace(1) - Linux manual page

プロセス1がシステムコールが実行されている時に、プロセス2がシステムコールを発行すると、時系列にトレースを出力するために、プロセス2のシステムコールをトレースに出力し、その後、終わっていなかったプロセス1のシステムコールを出力するときに resumed になるといった感じみたい。

2015-01-12

OpenJDK の HotSpot のソースコードを読む

素敵なサイト


ただのメモ

http://download.java.net/openjdk/jdk7/ から openjdk-7-fcs-src-b147-27_jun_2011.zipダウンロードする。

$ unzip openjdk-7-fcs-src-b147-27_jun_2011.zip
  • 覗いてみる
$ cd openjdk
$ tree -d -L 2
.
├── corba
│&#160;&#160; ├── make&#160;&#160; └── src
├── hotspot
│&#160;&#160; ├── agent&#160;&#160; ├── make&#160;&#160; ├── src&#160;&#160; └── test
├── jaxp
│&#160;&#160; ├── make&#160;&#160; ├── nbproject&#160;&#160; └── patches
├── jaxws
│&#160;&#160; ├── make&#160;&#160; ├── nbproject&#160;&#160; └── patches
├── jdk
│&#160;&#160; ├── make&#160;&#160; ├── src&#160;&#160; └── test
├── langtools
│&#160;&#160; ├── make&#160;&#160; ├── src&#160;&#160; └── test
├── make
│&#160;&#160; ├── scripts&#160;&#160; └── templates
└── test

28 directories

$ ack pthread_cond_wait *
hotspot/src/os/linux/vm/os_linux.cpp
4852://      a timeout request to the chron thread and then blocking via pthread_cond_wait().
4933:        status = pthread_cond_wait(_cond, _mutex);
5194:    status = pthread_cond_wait (_cond, _mutex) ;

hotspot/src/os/linux/vm/jsig.c
71:      pthread_cond_wait(&cond, &mutex);

hotspot/src/os/solaris/vm/os_solaris.cpp
4810:      os::Solaris::set_cond_wait(CAST_TO_FN_PTR(int_fnP_cond_tP_mutex_tP, resolve_symbol("pthread_cond_wait")));
$ ack pthread_cond_timedwait *             
hotspot/src/os/linux/vm/os_linux.cpp
4303:      return pthread_cond_timedwait(_cond, _mutex, _abstime);
4306:      // 6292965: LinuxThreads pthread_cond_timedwait() resets FPU control
4311:      int status = pthread_cond_timedwait(_cond, _mutex, _abstime);
4823:// Beware -- Some versions of NPTL embody a flaw where pthread_cond_timedwait() can
4827:// Briefly, pthread_cond_timedwait() calls with an expiry time that's not in the future
4832:// calls to pthread_cond_timedwait().  Using LD_ASSUME_KERNEL to use an older version
4839://      between the call to compute_abstime() and pthread_cond_timedwait(), more
4850:// 3.   Embargo pthread_cond_timedwait() and implement a native "chron" thread
4851://      that manages timeouts.  We'd emulate pthread_cond_timedwait() by enqueuing
4854://      on certain platforms that don't handle lots of active pthread_cond_timedwait()
4858://      correctly from pthread_cond_timedwait(), but the condvar is left corrupt.
4861://      followed by cond_init() -- after all calls to pthread_cond_timedwait().
4863://      value from pthread_cond_timedwait().  In addition to reinitializing the

hotspot/src/os/solaris/vm/os_solaris.cpp
4809:      os::Solaris::set_cond_timedwait(CAST_TO_FN_PTR(int_fnP_cond_tP_mutex_tP_timestruc_tP, resolve_symbol("pthread_cond_timedwait")));

hotspot/src/share/vm/runtime/globals.hpp
1073:         " avoid NPTL-FUTEX hang pthread_cond_timedwait" )                  \

参考

Linux 上での実装について

コメントによると, NPTL で pthread_cond_timedwait() がバグっていた時期があったらしい (永久にハングしてしまうんだとか).

以下の 4種類の解決策が考えられるが, 現在採用しているのは "4.". (WorkAroundNPTLTimedWaitHang オプションを参照).

(<= なおコメント中の WorkAroundNTPLTimedWaitHang は typo(TとPが逆))

なお, 「使用しているカーネルglibc のバージョンを確認して, バグっているバージョンの場合だけ対処する最適化も考えられる」とのこと.

    ((cite: hotspot/src/os/linux/vm/os_linux.cpp))
    // Refer to the comments in os_solaris.cpp park-unpark.
    //
    // Beware -- Some versions of NPTL embody a flaw where pthread_cond_timedwait() can
    // hang indefinitely.  For instance NPTL 0.60 on 2.4.21-4ELsmp is vulnerable.
    // For specifics regarding the bug see GLIBC BUGID 261237 :
    //    http://www.mail-archive.com/debian-glibc@lists.debian.org/msg10837.html.
    // Briefly, pthread_cond_timedwait() calls with an expiry time that's not in the future
    // will either hang or corrupt the condvar, resulting in subsequent hangs if the condvar
    // is used.  (The simple C test-case provided in the GLIBC bug report manifests the
    // hang).  The JVM is vulernable via sleep(), Object.wait(timo), LockSupport.parkNanos()
    // and monitorenter when we're using 1-0 locking.  All those operations may result in
    // calls to pthread_cond_timedwait().  Using LD_ASSUME_KERNEL to use an older version
    // of libpthread avoids the problem, but isn't practical.
    //
    // Possible remedies:
    //
    // 1.   Establish a minimum relative wait time.  50 to 100 msecs seems to work.
    //      This is palliative and probabilistic, however.  If the thread is preempted
    //      between the call to compute_abstime() and pthread_cond_timedwait(), more
    //      than the minimum period may have passed, and the abstime may be stale (in the
    //      past) resultin in a hang.   Using this technique reduces the odds of a hang
    //      but the JVM is still vulnerable, particularly on heavily loaded systems.
    //
    // 2.   Modify park-unpark to use per-thread (per ParkEvent) pipe-pairs instead
    //      of the usual flag-condvar-mutex idiom.  The write side of the pipe is set
    //      NDELAY. unpark() reduces to write(), park() reduces to read() and park(timo)
    //      reduces to poll()+read().  This works well, but consumes 2 FDs per extant
    //      thread.
    //
    // 3.   Embargo pthread_cond_timedwait() and implement a native "chron" thread
    //      that manages timeouts.  We'd emulate pthread_cond_timedwait() by enqueuing
    //      a timeout request to the chron thread and then blocking via pthread_cond_wait().
    //      This also works well.  In fact it avoids kernel-level scalability impediments
    //      on certain platforms that don't handle lots of active pthread_cond_timedwait()
    //      timers in a graceful fashion.
    //
    // 4.   When the abstime value is in the past it appears that control returns
    //      correctly from pthread_cond_timedwait(), but the condvar is left corrupt.
    //      Subsequent timedwait/wait calls may hang indefinitely.  Given that, we
    //      can avoid the problem by reinitializing the condvar -- by cond_destroy()
    //      followed by cond_init() -- after all calls to pthread_cond_timedwait().
    //      It may be possible to avoid reinitialization by checking the return
    //      value from pthread_cond_timedwait().  In addition to reinitializing the
    //      condvar we must establish the invariant that cond_signal() is only called
    //      within critical sections protected by the adjunct mutex.  This prevents
    //      cond_signal() from "seeing" a condvar that's in the midst of being
    //      reinitialized or that is corrupt.  Sadly, this invariant obviates the
    //      desirable signal-after-unlock optimization that avoids futile context switching.
    //
    //      I'm also concerned that some versions of NTPL might allocate an auxilliary
    //      structure when a condvar is used or initialized.  cond_destroy()  would
    //      release the helper structure.  Our reinitialize-after-timedwait fix
    //      put excessive stress on malloc/free and locks protecting the c-heap.
    //
    // We currently use (4).  See the WorkAroundNTPLTimedWaitHang flag.
    // It may be possible to refine (4) by checking the kernel and NTPL verisons
    // and only enabling the work-around for vulnerable environments.
Thread の待機処理の枠組み : ParkEvent (os::PlatformEvent) による処理

ほう。

Package: libc6

Version: 2.3.2.ds1-13

Severity: normal

pthread_cond_timedwait with a timespec in the past sometimes destroys the pthread_cond_t variable. The following pthread_cond_(timed)wait calls ignore all signals on the condition variable and block.

There is no Workaround, because I cannot guarantee that the timespec is really in the future (because the thread may be interrupted between gettimeofday and pthread_cond_timedwait).

The problem only occurs with NPTL (i.e. I can't reproduce the problem with LD_ASSUME_KERNEL=2.4.19).

The following program deadlocks after some iterations (10-1000).

&#42;** /tmp/current/bug.c
// gcc -pthread -Wall -O2 -std=c99    bug.c   -o bug

#include <stdio.h>
#include <pthread.h>

pthread_mutex_t mutex;
pthread_cond_t empty;
pthread_cond_t nonempty;
unsigned count = 0;

void* run(void* env)
{
    pthread_mutex_lock(&mutex);
    struct timespec ts = { 0, 0 };
    for (;;) {
        count = 0;
        pthread_cond_signal(&empty);
        pthread_cond_timedwait(&nonempty, &mutex, &ts);
        count = 0;
        pthread_cond_signal(&empty);
        pthread_cond_wait(&nonempty, &mutex);
    }
}

int main()
{
    pthread_mutex_init(&mutex, 0);
    pthread_cond_init(&empty, 0);
    pthread_cond_init(&nonempty, 0);

    pthread_t thread;
    pthread_create(&thread, 0, &run, 0);

    pthread_mutex_lock(&mutex);
    for (unsigned i = 0;; ++i) {
        while (count > 0) {
            pthread_cond_wait(&empty, &mutex);
        }
        ++count;
        pthread_cond_signal(&nonempty);
        printf("%u\n", i);
    }
}
    • System Information:

Debian Release: testing/unstable

APT prefers unstable

APT policy: (500, 'unstable')

Architecture: i386 (i686)

Kernel: Linux 2.6.7-1-686-smp

Locale: LANG=C, [EMAIL PROTECTED]

Versions of packages libc6 depends on:

ii libdb1-compat 2.1.3-7 The Berkeley database routines [gl

Bug#261237: NPTL: pthread_cond_timedwait with timespec in the past destroys cond variable

むむむ。

  • glibc_bug_261237.c
#include <stdio.h>
#include <pthread.h>

pthread_mutex_t mutex;
pthread_cond_t empty;
pthread_cond_t nonempty;
unsigned count = 0;

void* run(void* env)
{
    pthread_mutex_lock(&mutex);
    struct timespec ts = { 0, 0 };
    for (;;) {
        count = 0;
        pthread_cond_signal(&empty);
        pthread_cond_timedwait(&nonempty, &mutex, &ts);
        count = 0;
        pthread_cond_signal(&empty);
        pthread_cond_wait(&nonempty, &mutex);
    }
}

int main()
{
    pthread_mutex_init(&mutex, 0);
    pthread_cond_init(&empty, 0);
    pthread_cond_init(&nonempty, 0);

    pthread_t thread;
    pthread_create(&thread, 0, &run, 0);

    pthread_mutex_lock(&mutex);
    for (unsigned i = 0;; ++i) {
        while (count > 0) {
            pthread_cond_wait(&empty, &mutex);
        }
        ++count;
        pthread_cond_signal(&nonempty);
        printf("%u\n", i);
    }
}

glibc のバージョンを確認して

$ /lib/libc.so.6
GNU C Library stable release version 2.12, by Roland McGrath et al.
Copyright (C) 2010 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
Compiled by GNU CC version 4.4.7 20120313 (Red Hat 4.4.7-4).
Compiled on a Linux 2.6.32 system on 2013-11-20.
Available extensions:
	The C stubs add-on version 2.1.2.
	crypt add-on version 2.1 by Michael Glad and others
	GNU Libidn by Simon Josefsson
	Native POSIX Threads Library by Ulrich Drepper et al
	BIND-8.2.3-T5B
	RT using linux kernel aio
libc ABIs: UNIQUE IFUNC
For bug reporting instructions, please see:
<http://www.gnu.org/software/libc/bugs.html>.

コンパイルして

$ gcc -pthread -Wall -O2 -std=c99 glibc_bug_261237.c -o glibc_bug_261237

実行して、

$ ./glibc_bug_261237 > /dev/null &
[1] 24235

まずは dstat で

$ dstat -tcf --top-cpu 5 
----system---- -------cpu0-usage--------------cpu1-usage--------------cpu2-usage--------------cpu3-usage------ -most-expensive-
  date/time   |usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq|  cpu process   
12-01 13:33:00| 18  21  60   0   0   0: 18  20  62   0   0   0: 15  27  58   0   0   0: 16  27  56   0   0   0|glibc_bug_2614.4
12-01 13:33:05|  5  12  83   0   0   0:  5   9  86   0   0   0: 10  50  39   0   0   1: 14  44  42   0   0   0|glibc_bug_261 30
12-01 13:33:10| 11  45  44   0   0   0: 13  39  48   0   0   0:  5  12  83   0   0   0:  4  12  84   0   0   0|glibc_bug_261 29
12-01 13:33:15| 12  52  36   0   0   1: 15  43  42   0   0   0:  4   9  86   0   0   0:  4   8  88   0   0   0|glibc_bug_261 29
12-01 13:33:20|  8  35  56   0   0   0: 10  29  61   0   0   0:  7  20  72   0   0   0:  6  22  72   0   0   0|glibc_bug_261 29

top で眺めてみる

$ top -Hc -b -d 5 -p 24235
top - 13:14:50 up  3:05,  3 users,  load average: 1.42, 1.16, 1.06
Tasks:   2 total,   1 running,   1 sleeping,   0 stopped,   0 zombie
Cpu(s): 19.6%us, 21.7%sy,  0.3%ni, 57.8%id,  0.4%wa,  0.0%hi,  0.2%si,  0.0%st
Mem:  16158544k total, 15997144k used,   161400k free,   225588k buffers
Swap:  8085500k total,        0k used,  8085500k free,  5224448k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                            
24235 yazekats  20   0 14464  316  248 R 63.9  0.0   7:24.87 ./glibc_bug_261237
24236 yazekats  20   0 14464  316  248 S 59.9  0.0   7:12.00 ./glibc_bug_261237                 

[...]

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                            
24235 yazekats  20   0 14464  316  248 R 60.6  0.0   7:27.90 ./glibc_bug_261237
24236 yazekats  20   0 14464  316  248 S 59.0  0.0   7:14.95 ./glibc_bug_261237

[...]

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND   
24235 yazekats  20   0 14464  316  248 R 61.9  0.0   7:31.00 ./glibc_bug_261237
24236 yazekats  20   0 14464  316  248 R 59.7  0.0   7:17.94 ./glibc_bug_261237            

strace -ttT したり

$ strace -ttT -p 24235
13:17:59.132997 futex(0x600d24, FUTEX_WAIT_PRIVATE, 257305127, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
13:17:59.133086 futex(0x600d64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x600d60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000025>
13:17:59.133180 futex(0x600ce0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000025>
13:17:59.133270 futex(0x600d20, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000031>
13:17:59.133370 futex(0x600d24, FUTEX_WAIT_PRIVATE, 257305129, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
13:17:59.133459 futex(0x600d64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x600d60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000024>
13:17:59.133552 futex(0x600ce0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000024>
13:17:59.133642 futex(0x600d20, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000031>
13:17:59.133743 futex(0x600d24, FUTEX_WAIT_PRIVATE, 257305131, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000021>
13:17:59.133841 futex(0x600d64, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x600d60, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 <0.000025>
13:17:59.133936 futex(0x600ce0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000026>
13:17:59.134027 futex(0x600d20, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000031>
13:17:59.134127 futex(0x600d24, FUTEX_WAIT_PRIVATE, 257305133, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000020>
^CProcess 24235 detached

strace -c したり

$ strace -c -p 24235
Process 24235 attached - interrupt to quit
^CProcess 24235 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.010504           0     49197     12280 futex
  0.00    0.000000           0        30           write
------ ----------- ----------- --------- --------- ----------------
100.00    0.010504                 49227     12280 total

ltrace してみたり

$ ltrace -ttTSC -n 4 -p 4454
[pid 4455] 16:06:08.972344 pthread_cond_wait(0x600d60, 0x600ce0, 1, -1, 0x600d20 <unfinished ...>
[pid 4454] 16:06:08.972523     <... SYS_futex resumed> )                                               = -512 <0.000157>
[pid 4455] 16:06:08.972573     SYS_futex(0x600ce0, 129, 1, 1, 0x600d20 <unfinished ...>
[pid 4454] 16:06:08.972642     SYS_futex(0x600ce0, 128, 2, 0, 0x600ce0 <unfinished ...>
[pid 4455] 16:06:08.972738     <... SYS_futex resumed> )                                               = 0 <0.000077>
[pid 4454] 16:06:08.972794     <... SYS_futex resumed> )                                               = -11 <0.000063>
[pid 4455] 16:06:08.972829     SYS_futex(0x600d64, 128, 0x3dbc1ef, 0, 0x600c00 <unfinished ...>
[pid 4454] 16:06:08.972931 <... pthread_cond_wait resumed> )                                           = 0 <0.001707>
[pid 4454] 16:06:08.972969 pthread_cond_signal(0x600d60, 128, 0, -1, 0x600ce0 <unfinished ...>
[pid 4455] 16:06:08.973149     <... SYS_futex resumed> )                                               = -512 <0.000226>
[pid 4455] 16:06:08.973199     SYS_futex(0x600d64, 128, 0x3dbc1ef, 0, 0x600c00 <unfinished ...>
[pid 4454] 16:06:08.973267     SYS_futex(0x600d64, 133, 1, 1, 0x600d60 <unfinished ...>
[pid 4455] 16:06:08.973355     <... SYS_futex resumed> )                                               = -11 <0.000070>
[pid 4454] 16:06:08.973412     <... SYS_futex resumed> )                                               = 0 <0.000063>
[pid 4455] 16:06:08.973445     SYS_futex(0x600ce0, 128, 2, 0, 0x600ce0 <unfinished ...>
[pid 4454] 16:06:08.973541 <... pthread_cond_signal resumed> )                                         = 0 <0.000471>
[pid 4454] 16:06:08.973579 printf("%u\n", 32350362 <unfinished ...>
[pid 4455] 16:06:08.973748     <... SYS_futex resumed> )                                               = ^C-512 <0.000214>
$ ltrace -c -p 24235
^C% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 50.53    6.287200        2779      2262 pthread_cond_wait
 22.54    2.803753         929      3017 pthread_cond_signal
 19.67    2.447685        1623      1508 printf
  7.26    0.902921        1197       754 pthread_cond_timedwait
------ ----------- ----------- --------- --------------------
100.00   12.441559                  7541 total

perf してみたり

$ sudo echo 0 > /proc/sys/kernel/perf_event_paranoid
$ perf record -F 99 -p 24235
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.021 MB perf.data (~922 samples) ]
$ perf report
Samples: 305  of event 'cycles:HG', Event count (approx.): 2873553649
 10.73%  glibc_bug_26123  [kernel.kallsyms]   [k] _raw_spin_unlock_irqrestore ★これを選択
  8.22%  glibc_bug_26123  [kernel.kallsyms]   [k] try_to_wake_up
  7.83%  glibc_bug_26123  libc-2.12.so        [.] vfprintf
  3.89%  glibc_bug_26123  [kernel.kallsyms]   [k] native_write_msr_safe
  3.88%  glibc_bug_26123  [kernel.kallsyms]   [k] __ticket_spin_lock
  3.08%  glibc_bug_26123  libpthread-2.12.so  [.] pthread_cond_wait@@GLIBC_2.3.2
  2.97%  glibc_bug_26123  [kernel.kallsyms]   [k] futex_wake_op
  2.83%  glibc_bug_26123  libc-2.12.so        [.] free
  2.79%  glibc_bug_26123  [kernel.kallsyms]   [k] system_call
  2.68%  glibc_bug_26123  [kernel.kallsyms]   [k] system_call_after_swapgs
  2.57%  glibc_bug_26123  [kernel.kallsyms]   [k] get_futex_key
  2.37%  glibc_bug_26123  [kernel.kallsyms]   [k] __schedule
  2.31%  glibc_bug_26123  libc-2.12.so        [.] _itoa_word
  2.12%  glibc_bug_26123  libpthread-2.12.so  [.] pthread_cond_signal@@GLIBC_2.3.2
  1.88%  glibc_bug_26123  [kernel.kallsyms]   [k] __x2apic_send_IPI_mask
  1.84%  glibc_bug_26123  [kernel.kallsyms]   [k] futex_wait
  1.77%  glibc_bug_26123  libpthread-2.12.so  [.] __lll_unlock_wake
  1.76%  glibc_bug_26123  [kernel.kallsyms]   [k] select_task_rq_fair
  1.58%  glibc_bug_26123  libc-2.12.so        [.] _IO_file_xsputn@@GLIBC_2.2.5
  1.57%  glibc_bug_26123  [kernel.kallsyms]   [k] hash_futex
  1.47%  glibc_bug_26123  [kernel.kallsyms]   [k] native_read_tsc
  1.39%  glibc_bug_26123  libc-2.12.so        [.] __strchrnul
  1.38%  glibc_bug_26123  [kernel.kallsyms]   [k] find_next_bit
  1.28%  glibc_bug_26123  [kernel.kallsyms]   [k] wake_futex
  1.25%  glibc_bug_26123  [kernel.kallsyms]   [k] perf_event_context_sched_out
  1.25%  glibc_bug_26123  [kernel.kallsyms]   [k] dequeue_task
  1.19%  glibc_bug_26123  [kernel.kallsyms]   [k] effective_load
  1.15%  glibc_bug_26123  [kernel.kallsyms]   [k] wake_affine
  1.11%  glibc_bug_26123  [kernel.kallsyms]   [k] dequeue_entity
  1.03%  glibc_bug_26123  [kernel.kallsyms]   [k] cpumask_next_and
  0.92%  glibc_bug_26123  [kernel.kallsyms]   [k] intel_pmu_enable_all
  0.90%  glibc_bug_26123  [kernel.kallsyms]   [k] sys_futex
  0.78%  glibc_bug_26123  [kernel.kallsyms]   [k] pick_next_task_idle
  0.76%  glibc_bug_26123  [kernel.kallsyms]   [k] copy_user_generic_string
  0.75%  glibc_bug_26123  [kernel.kallsyms]   [k] pick_next_task_fair
Press '?' for help on key bindings

脱線