1

I am playing with perf to learn how can one figure out why process enters "D" (uninterruptible sleep) state.

I am using perf command:

perf record -g -p 4710 -e sched:sched_stat_iowait,sched:sched_stat_blocked sleep 60

where 4710 is pid of my process called meetmaker.

Then I am looking at perf script output which is

meetmaker-3.0.0  4710 [008] 19187729.668851: sched:sched_stat_iowait: comm=jbd2/dm-2-8 pid=697 delay=120641 [ns]
        ffffffff810a08a0 enqueue_sleeper ([kernel.kallsyms])
        ffffffff810a08a0 enqueue_sleeper ([kernel.kallsyms])
        ffffffff810a756a enqueue_entity ([kernel.kallsyms])
        ffffffff810a7e83 enqueue_task_fair ([kernel.kallsyms])
        ffffffff810967b1 ttwu_activate ([kernel.kallsyms])
        ffffffff81096983 ttwu_do_activate ([kernel.kallsyms])
        ffffffff8109819a ttwu_queue ([kernel.kallsyms])
        ffffffff810983fe try_to_wake_up ([kernel.kallsyms])
        ffffffff810ada66 autoremove_wake_function ([kernel.kallsyms])
        ffffffff810ad8fa __wake_up_common ([kernel.kallsyms])
        ffffffff810addb8 __wake_up ([kernel.kallsyms])
        ffffffff810ade11 __wake_up_bit ([kernel.kallsyms])
        ffffffff81260fcb ext4_finish_bio ([kernel.kallsyms])
        ffffffff812617df ext4_end_bio ([kernel.kallsyms])
        ffffffff8131b433 blk_update_request ([kernel.kallsyms])
        ffffffff8131b5b7 blk_update_bidi_request ([kernel.kallsyms])
        ffffffff8131c9af blk_end_bidi_request ([kernel.kallsyms])
        ffffffff8148f1f0 scsi_io_completion ([kernel.kallsyms])
        ffffffff813263bb blk_done_softirq ([kernel.kallsyms])
        ffffffff8106af9c __do_softirq ([kernel.kallsyms])
        ffffffff8106b1e5 irq_exit ([kernel.kallsyms])
        ffffffff816399fa do_IRQ ([kernel.kallsyms])
        ffffffff8163796d ret_from_intr ([kernel.kallsyms])
                  487f77 [unknown] ([unknown])
                  487f77 meetmaker__user_counters_get (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  505cff gpbrpc_exec (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  4eb45c ipc_game_loop (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  4ed48a game (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  48ebe3 service_late_init (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  47371a main (/local/meetmaker/bin/meetmaker-3.0.0_2724)
            7fd3cc391c36 __libc_start_main (/lib64/libc-2.11.3.so)

meetmaker-3.0.0  4710 [008] 19187729.668886: sched:sched_stat_blocked: comm=jbd2/dm-2-8 pid=697 delay=120641 [ns]
        ffffffff810a08d8 enqueue_sleeper ([kernel.kallsyms])
        ffffffff810a08d8 enqueue_sleeper ([kernel.kallsyms])
        ffffffff810a756a enqueue_entity ([kernel.kallsyms])
        ffffffff810a7e83 enqueue_task_fair ([kernel.kallsyms])
        ffffffff810967b1 ttwu_activate ([kernel.kallsyms])
        ffffffff81096983 ttwu_do_activate ([kernel.kallsyms])
        ffffffff8109819a ttwu_queue ([kernel.kallsyms])
        ffffffff810983fe try_to_wake_up ([kernel.kallsyms])
        ffffffff810ada66 autoremove_wake_function ([kernel.kallsyms])
        ffffffff810ad8fa __wake_up_common ([kernel.kallsyms])
        ffffffff810addb8 __wake_up ([kernel.kallsyms])
        ffffffff810ade11 __wake_up_bit ([kernel.kallsyms])
        ffffffff81260fcb ext4_finish_bio ([kernel.kallsyms])
        ffffffff812617df ext4_end_bio ([kernel.kallsyms])
        ffffffff8131b433 blk_update_request ([kernel.kallsyms])
        ffffffff8131b5b7 blk_update_bidi_request ([kernel.kallsyms])
        ffffffff8131c9af blk_end_bidi_request ([kernel.kallsyms])
        ffffffff8148f1f0 scsi_io_completion ([kernel.kallsyms])
        ffffffff813263bb blk_done_softirq ([kernel.kallsyms])
        ffffffff8106af9c __do_softirq ([kernel.kallsyms])
        ffffffff8106b1e5 irq_exit ([kernel.kallsyms])
        ffffffff816399fa do_IRQ ([kernel.kallsyms])
        ffffffff8163796d ret_from_intr ([kernel.kallsyms])
                  487f77 [unknown] ([unknown])
                  487f77 meetmaker__user_counters_get (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  505cff gpbrpc_exec (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  4eb45c ipc_game_loop (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  4ed48a game (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  48ebe3 service_late_init (/local/meetmaker/bin/meetmaker-3.0.0_2724)
                  47371a main (/local/meetmaker/bin/meetmaker-3.0.0_2724)
            7fd3cc391c36 __libc_start_main (/lib64/libc-2.11.3.so)

As far as I understand this perf output, it is jbd kernel thread that is in D state and it preempted my meetmaker process. It is not that meetmaker process entered D state, right?

So it is not what I am looking for. Even though I gave -p argument to perf, it gave me another process that I am not interested in.

Am I right?

Is this a best way to figure out when and why any particular process enters "D" state?

Marko Kevac
  • 2,902
  • 30
  • 47

2 Answers2

0

perf is the wrong tool here. You can trace such state transitions with systemtap.

However, there is no magic rule. You have to investigate each place separately.

0

D state is a kernel state entered when some kernel process has to wait for some driver event that for sure is going to happen, and cannot accept signals (even non ignorable ones, like SIGKILL or SIGSTOP). A signal normally gets out of the normal program flow, so it's somewhat common in user space (you as a user want to be able to interrupt your programs) but in kernel space there are processes (related to driver work) that would lead the driver data in a unstable state if allowed to be interrupted (suppose you program some device to interrupt you and you are not there to acknowledge the interrupt. You'll get a device lock), so the kernel has this state for that (D stands for Driver state? can somebody confirm this?). Suppose you are reading some disk data and you have programmed the controller chip to interrupt you, you have to wait for the disk to transfer all the block data to kernel buffers and interrupt you. The interrupt is to come in some millisecs or usecs, for sure... but if you interrupt the process in the middle there would be no process to awake, there's nothing to acknowledge the device interrupt and the device will be blocked. D state is something driver dependant. Kernel enters this state on a durable operation when it enters driver code (driver writers call specifically wait__non_interruptable functions to get it) to make some specific task.

As so, it is not interruptible, you have to wait for it to get out by itself. This means you cannot kill the process from user space anyway and having one of these things locking your system normally means some driver bug.

Luis Colorado
  • 10,974
  • 1
  • 16
  • 31