Lines Matching refs:us
862 # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
878 ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
879 ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
880 ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
881 ps-6143 2d..1 306us : <stack trace>
897 (3.8). Then it displays the max latency in microseconds (259 us). The number
1318 # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1334 <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
1335 <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
1336 <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
1337 <idle>-0 0dNs3 25us : <stack trace>
1356 timestamp 25us occurred because the clock was incremented
1369 # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1385 bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1386 bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
1387 bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
1388 bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
1389 bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
1390 bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
1391 bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
1392 bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
1393 bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
1395 bash-2042 3d..1 67us : delay_tsc <-__delay
1396 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1397 bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
1398 bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
1399 bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
1400 bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
1401 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1402 bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1403 bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
1404 bash-2042 3d..1 120us : <stack trace>
1447 # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
1462 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
1463 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1464 1 us | 0) bash-1507 | d..2 | | set_track() {
1465 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
1466 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
1467 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
1468 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
1469 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
1470 4 us | 0) bash-1507 | d..2 | 1.107 us | }
1472 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
1473 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
1474 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
1475 bash-1507 0d..1 3792us : <stack trace>
1517 # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1533 sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
1534 sshd-1991 1d..1 46us : irq_exit <-do_IRQ
1535 sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
1536 sshd-1991 1d..1 52us : <stack trace>
1555 # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1571 bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
1572 bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
1573 bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
1574 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1575 bash-1994 1d..1 1us : source_load <-select_task_rq_fair
1577 bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
1578 bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
1579 bash-1994 1d..1 13us : add_preempt_count <-irq_enter
1580 bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
1581 bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
1582 bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
1583 bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
1584 bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
1586 bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
1587 bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
1588 bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
1589 bash-1994 1d..2 36us : do_softirq <-irq_exit
1590 bash-1994 1d..2 36us : __do_softirq <-call_softirq
1591 bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
1592 bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
1593 bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
1594 bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
1595 bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
1597 bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
1598 bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
1599 bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
1600 bash-1994 1dN.2 82us : idle_cpu <-irq_exit
1601 bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
1602 bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
1603 bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
1604 bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
1605 bash-1994 1.N.1 104us : <stack trace>
1617 the entire time. The irq_enter code lets us know that we entered
1669 # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1685 ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
1686 ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
1687 ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
1688 ls-2230 3...1 111us : <stack trace>
1722 # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1738 kworker/-59 3...1 0us : __schedule <-schedule
1739 kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
1740 kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
1741 kworker/-59 3d..2 1us : deactivate_task <-__schedule
1742 kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
1743 kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
1744 kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
1745 kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
1746 kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
1747 kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
1748 kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
1749 kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
1750 kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
1751 kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
1752 kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
1753 kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
1754 kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
1755 kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
1756 kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
1757 kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
1758 kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
1759 kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
1760 kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
1761 kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
1762 kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
1763 ls-2269 3d..2 7us : finish_task_switch <-__schedule
1764 ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
1765 ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
1766 ls-2269 3d..2 8us : irq_enter <-do_IRQ
1767 ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
1768 ls-2269 3d..2 9us : add_preempt_count <-irq_enter
1769 ls-2269 3d.h2 9us : exit_idle <-do_IRQ
1771 ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
1772 ls-2269 3d.h2 20us : irq_exit <-do_IRQ
1773 ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
1774 ls-2269 3d..3 21us : do_softirq <-irq_exit
1775 ls-2269 3d..3 21us : __do_softirq <-call_softirq
1776 ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
1777 ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
1778 ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
1779 ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
1780 ls-2269 3d.s5 31us : irq_enter <-do_IRQ
1781 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1783 ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
1784 ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
1785 ls-2269 3d.H5 32us : exit_idle <-do_IRQ
1786 ls-2269 3d.H5 32us : handle_irq <-do_IRQ
1787 ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
1788 ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
1790 ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
1791 ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
1792 ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
1793 ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
1794 ls-2269 3d..3 159us : idle_cpu <-irq_exit
1795 ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
1796 ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
1797 ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
1798 ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
1799 ls-2269 3d... 186us : <stack trace>
1838 # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1851 <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
1852 <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1853 <idle>-0 3d..3 15us : __schedule <-schedule
1854 <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
1907 # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1920 <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
1921 <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
1922 <idle>-0 3d..3 5us : __schedule <-schedule
1923 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1940 <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
1956 # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
1969 <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
1970 <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
1971 <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
1972 <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
1973 <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
1974 <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
1975 <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
1976 <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
1977 <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
1978 <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
1979 <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
1980 <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
1981 <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
1982 <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
1983 <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
1984 <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
1985 <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
1986 <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
1987 <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
1988 <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
1989 <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
1990 <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
1991 <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
1992 <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
1993 <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
1994 <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
1995 <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
1996 <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
1997 <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
1998 <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
1999 <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
2000 <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
2001 <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
2002 <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
2003 <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
2004 <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
2005 <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
2006 <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
2007 <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
2008 <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
2009 <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
2010 <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
2011 <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2012 <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
2013 <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
2014 <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
2015 <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
2016 <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
2017 <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
2018 <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
2019 <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
2020 <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2021 <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
2022 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2023 <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
2024 <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
2025 <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
2026 <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
2027 <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
2028 <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
2029 <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
2030 <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
2031 <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
2032 <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
2033 <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
2034 <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
2035 <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
2036 <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
2037 <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
2038 <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
2039 <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
2040 <idle>-0 3.N.. 25us : schedule <-cpu_idle
2041 <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
2042 <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
2043 <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
2044 <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
2045 <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
2046 <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
2047 <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
2048 <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
2049 <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
2050 <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
2051 <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
2052 <idle>-0 3d..3 29us : __schedule <-preempt_schedule
2053 <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
2082 # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
2095 <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
2096 <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
2097 <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
2098 <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
2099 <idle>-0 2.N.2 2us : power_end: cpu_id=2
2100 <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
2101 <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
2102 …<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer ex…
2103 <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
2104 <idle>-0 2.N.2 5us : rcu_utilization: End context switch
2105 <idle>-0 2d..3 6us : __schedule <-schedule
2106 <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
2130 … <...>-3638 [001] d... 19452.055471: #1 inner/outer(us): 12/14 ts:1499801089.066141940
2131 … <...>-3638 [003] d... 19454.071354: #2 inner/outer(us): 11/9 ts:1499801091.082164365
2132 … <...>-3638 [002] dn.. 19461.126852: #3 inner/outer(us): 12/9 ts:1499801098.138150062
2133 … <...>-3638 [001] d... 19488.340960: #4 inner/outer(us): 8/12 ts:1499801125.354139633
2134 … <...>-3638 [003] d... 19494.388553: #5 inner/outer(us): 8/12 ts:1499801131.402150961
2135 …<...>-3638 [003] d... 19501.283419: #6 inner/outer(us): 0/12 ts:1499801138.297435289 nm…
2145 inner/outer(us): 12/14
2434 0) 1.382 us | __might_sleep();
2435 0) 2.478 us | }
2438 0) 1.389 us | __might_sleep();
2439 0) 2.553 us | }
2440 0) 3.807 us | }
2441 0) 7.876 us | }
2443 0) 0.668 us | _spin_lock();
2444 0) 0.570 us | expand_files();
2445 0) 0.586 us | _spin_unlock();
2477 3) # 1837.709 us | } /* __switch_to */
2479 3) 0.313 us | _raw_spin_unlock_irq();
2480 3) 3.177 us | }
2481 3) # 1889.063 us | } /* __schedule */
2482 3) ! 140.417 us | } /* __schedule */
2483 3) # 2034.948 us | } /* schedule */
2484 3) * 33998.59 us | } /* schedule_preempt_disabled */
2488 1) 0.260 us | msecs_to_jiffies();
2489 1) 0.313 us | __rcu_read_unlock();
2490 1) + 61.770 us | }
2491 1) + 64.479 us | }
2492 1) 0.313 us | rcu_bh_qs();
2493 1) 0.313 us | __local_bh_enable();
2494 1) ! 217.240 us | }
2495 1) 0.365 us | idle_cpu();
2497 1) 0.417 us | rcu_eqs_enter_common.isra.47();
2498 1) 3.125 us | }
2499 1) ! 227.812 us | }
2500 1) ! 457.395 us | }
2501 1) @ 119760.2 us | }
2506 1) 6.979 us | }
2507 2) 0.417 us | scheduler_ipi();
2508 1) 9.791 us | }
2509 1) + 12.917 us | }
2510 2) 3.490 us | }
2511 1) + 15.729 us | }
2512 1) + 18.542 us | }
2513 2) $ 3594274 us | }
2540 0) sh-4802 | 0.616 us | rcu_process_gp_end();
2541 0) sh-4802 | 0.586 us | check_for_new_grace_period();
2542 0) sh-4802 | 2.899 us | }
2543 0) sh-4802 | 4.040 us | }
2544 0) sh-4802 | 5.151 us | }
2545 0) sh-4802 | + 49.370 us | }
2560 360.774522 | 1) 0.541 us | }
2561 360.774522 | 1) 4.663 us | }
2562 360.774523 | 1) 0.541 us | __wake_up_bit();
2563 360.774524 | 1) 6.796 us | }
2564 360.774524 | 1) 7.952 us | }
2565 360.774525 | 1) 9.063 us | }
2566 360.774525 | 1) 0.615 us | journal_mark_dirty();
2567 360.774527 | 1) 0.578 us | __brelse();
2572 360.774530 | 1) 0.594 us | __phys_addr();
2591 0) 0.518 us | __phys_addr();
2592 0) 1.757 us | }
2593 0) 2.861 us | }
2599 0) 0.518 us | __phys_addr();
2600 0) 1.757 us | } /* kmem_cache_free() */
2601 0) 2.861 us | } /* putname() */
2614 1) 1.449 us | }
2929 0) 0.804 us | find_get_page();
2931 0) 1.329 us | }
2932 0) 3.904 us | }
2933 0) 4.979 us | }
2934 0) 0.653 us | _spin_lock();
2935 0) 0.578 us | page_add_file_rmap();
2936 0) 0.525 us | native_set_pte_at();
2937 0) 0.585 us | _spin_unlock();
2939 0) 0.541 us | page_waitqueue();
2940 0) 0.639 us | __wake_up_bit();
2941 0) 2.786 us | }
2942 0) + 14.237 us | }
2946 0) 0.698 us | find_get_page();
2948 0) 1.412 us | }
2949 0) 3.950 us | }
2950 0) 5.098 us | }
2951 0) 0.631 us | _spin_lock();
2952 0) 0.571 us | page_add_file_rmap();
2953 0) 0.526 us | native_set_pte_at();
2954 0) 0.586 us | _spin_unlock();
2956 0) 0.533 us | page_waitqueue();
2957 0) 0.638 us | __wake_up_bit();
2958 0) 2.793 us | }
2959 0) + 14.012 us | }