docs: ftrace: always use canonical ftrace path

+2 -2

Documentation/admin-guide/kernel-parameters.txt

··· 6288 6288 that can be enabled or disabled just as if you were 6289 6289 to echo the option name into 6290 6290 6291 - /sys/kernel/debug/tracing/trace_options 6291 + /sys/kernel/tracing/trace_options 6292 6292 6293 6293 For example, to enable stacktrace option (to dump the 6294 6294 stack trace of each event), add to the command line: ··· 6321 6321 [FTRACE] enable this option to disable tracing when a 6322 6322 warning is hit. This turns off "tracing_on". Tracing can 6323 6323 be enabled again by echoing '1' into the "tracing_on" 6324 - file located in /sys/kernel/debug/tracing/ 6324 + file located in /sys/kernel/tracing/ 6325 6325 6326 6326 This option is useful, as it disables the trace before 6327 6327 the WARNING dump is called, which prevents the trace to

+1 -1

Documentation/admin-guide/kernel-per-CPU-kthreads.rst

··· 25 25 26 26 - In order to locate kernel-generated OS jitter on CPU N: 27 27 28 - cd /sys/kernel/debug/tracing 28 + cd /sys/kernel/tracing 29 29 echo 1 > max_graph_depth # Increase the "1" for more detail 30 30 echo function_graph > current_tracer 31 31 # run workload

+2 -2

Documentation/admin-guide/pm/intel_pstate.rst

··· 712 712 The following sequence of shell commands can be used to enable them and see 713 713 their output (if the kernel is generally configured to support event tracing):: 714 714 715 - # cd /sys/kernel/debug/tracing/ 715 + # cd /sys/kernel/tracing/ 716 716 # echo 1 > events/power/pstate_sample/enable 717 717 # echo 1 > events/power/cpu_frequency/enable 718 718 # cat trace ··· 732 732 P-state is called, the ``ftrace`` filter can be set to 733 733 :c:func:`intel_pstate_set_pstate`:: 734 734 735 - # cd /sys/kernel/debug/tracing/ 735 + # cd /sys/kernel/tracing/ 736 736 # cat available_filter_functions | grep -i pstate 737 737 intel_pstate_set_pstate 738 738 intel_pstate_cpu_init

+2 -2

Documentation/core-api/workqueue.rst

··· 370 370 371 371 The first one can be tracked using tracing: :: 372 372 373 - $ echo workqueue:workqueue_queue_work > /sys/kernel/debug/tracing/set_event 374 - $ cat /sys/kernel/debug/tracing/trace_pipe > out.txt 373 + $ echo workqueue:workqueue_queue_work > /sys/kernel/tracing/set_event 374 + $ cat /sys/kernel/tracing/trace_pipe > out.txt 375 375 (wait a few secs) 376 376 ^C 377 377

+2 -2

Documentation/hid/intel-ish-hid.rst

··· 344 344 345 345 To debug ISH, event tracing mechanism is used. To enable debug logs:: 346 346 347 - echo 1 > /sys/kernel/debug/tracing/events/intel_ish/enable 348 - cat /sys/kernel/debug/tracing/trace 347 + echo 1 > /sys/kernel/tracing/events/intel_ish/enable 348 + cat /sys/kernel/tracing/trace 349 349 350 350 3.8 ISH IIO sysfs Example on Lenovo thinkpad Yoga 260 351 351 -----------------------------------------------------

+46 -46

Documentation/networking/device_drivers/ethernet/mellanox/mlx5.rst

··· 548 548 mlx5 driver provides internal tracepoints for tracking and debugging using 549 549 kernel tracepoints interfaces (refer to Documentation/trace/ftrace.rst). 550 550 551 - For the list of support mlx5 events, check `/sys/kernel/debug/tracing/events/mlx5/`. 551 + For the list of support mlx5 events, check /sys/kernel/tracing/events/mlx5/ 552 552 553 553 tc and eswitch offloads tracepoints: 554 554 555 555 - mlx5e_configure_flower: trace flower filter actions and cookies offloaded to mlx5:: 556 556 557 - $ echo mlx5:mlx5e_configure_flower >> /sys/kernel/debug/tracing/set_event 558 - $ cat /sys/kernel/debug/tracing/trace 557 + $ echo mlx5:mlx5e_configure_flower >> /sys/kernel/tracing/set_event 558 + $ cat /sys/kernel/tracing/trace 559 559 ... 560 560 tc-6535 [019] ...1 2672.404466: mlx5e_configure_flower: cookie=0000000067874a55 actions= REDIRECT 561 561 562 562 - mlx5e_delete_flower: trace flower filter actions and cookies deleted from mlx5:: 563 563 564 - $ echo mlx5:mlx5e_delete_flower >> /sys/kernel/debug/tracing/set_event 565 - $ cat /sys/kernel/debug/tracing/trace 564 + $ echo mlx5:mlx5e_delete_flower >> /sys/kernel/tracing/set_event 565 + $ cat /sys/kernel/tracing/trace 566 566 ... 567 567 tc-6569 [010] .N.1 2686.379075: mlx5e_delete_flower: cookie=0000000067874a55 actions= NULL 568 568 569 569 - mlx5e_stats_flower: trace flower stats request:: 570 570 571 - $ echo mlx5:mlx5e_stats_flower >> /sys/kernel/debug/tracing/set_event 572 - $ cat /sys/kernel/debug/tracing/trace 571 + $ echo mlx5:mlx5e_stats_flower >> /sys/kernel/tracing/set_event 572 + $ cat /sys/kernel/tracing/trace 573 573 ... 574 574 tc-6546 [010] ...1 2679.704889: mlx5e_stats_flower: cookie=0000000060eb3d6a bytes=0 packets=0 lastused=4295560217 575 575 576 576 - mlx5e_tc_update_neigh_used_value: trace tunnel rule neigh update value offloaded to mlx5:: 577 577 578 - $ echo mlx5:mlx5e_tc_update_neigh_used_value >> /sys/kernel/debug/tracing/set_event 579 - $ cat /sys/kernel/debug/tracing/trace 578 + $ echo mlx5:mlx5e_tc_update_neigh_used_value >> /sys/kernel/tracing/set_event 579 + $ cat /sys/kernel/tracing/trace 580 580 ... 581 581 kworker/u48:4-8806 [009] ...1 55117.882428: mlx5e_tc_update_neigh_used_value: netdev: ens1f0 IPv4: 1.1.1.10 IPv6: ::ffff:1.1.1.10 neigh_used=1 582 582 583 583 - mlx5e_rep_neigh_update: trace neigh update tasks scheduled due to neigh state change events:: 584 584 585 - $ echo mlx5:mlx5e_rep_neigh_update >> /sys/kernel/debug/tracing/set_event 586 - $ cat /sys/kernel/debug/tracing/trace 585 + $ echo mlx5:mlx5e_rep_neigh_update >> /sys/kernel/tracing/set_event 586 + $ cat /sys/kernel/tracing/trace 587 587 ... 588 588 kworker/u48:7-2221 [009] ...1 1475.387435: mlx5e_rep_neigh_update: netdev: ens1f0 MAC: 24:8a:07:9a:17:9a IPv4: 1.1.1.10 IPv6: ::ffff:1.1.1.10 neigh_connected=1 589 589 ··· 592 592 - mlx5_esw_bridge_fdb_entry_init: trace bridge FDB entry offloaded to mlx5:: 593 593 594 594 $ echo mlx5:mlx5_esw_bridge_fdb_entry_init >> set_event 595 - $ cat /sys/kernel/debug/tracing/trace 595 + $ cat /sys/kernel/tracing/trace 596 596 ... 597 597 kworker/u20:9-2217 [003] ...1 318.582243: mlx5_esw_bridge_fdb_entry_init: net_device=enp8s0f0_0 addr=e4:fd:05:08:00:02 vid=0 flags=0 used=0 598 598 599 599 - mlx5_esw_bridge_fdb_entry_cleanup: trace bridge FDB entry deleted from mlx5:: 600 600 601 601 $ echo mlx5:mlx5_esw_bridge_fdb_entry_cleanup >> set_event 602 - $ cat /sys/kernel/debug/tracing/trace 602 + $ cat /sys/kernel/tracing/trace 603 603 ... 604 604 ip-2581 [005] ...1 318.629871: mlx5_esw_bridge_fdb_entry_cleanup: net_device=enp8s0f0_1 addr=e4:fd:05:08:00:03 vid=0 flags=0 used=16 605 605 ··· 607 607 mlx5:: 608 608 609 609 $ echo mlx5:mlx5_esw_bridge_fdb_entry_refresh >> set_event 610 - $ cat /sys/kernel/debug/tracing/trace 610 + $ cat /sys/kernel/tracing/trace 611 611 ... 612 612 kworker/u20:8-3849 [003] ...1 466716: mlx5_esw_bridge_fdb_entry_refresh: net_device=enp8s0f0_0 addr=e4:fd:05:08:00:02 vid=3 flags=0 used=0 613 613 ··· 615 615 representor:: 616 616 617 617 $ echo mlx5:mlx5_esw_bridge_vlan_create >> set_event 618 - $ cat /sys/kernel/debug/tracing/trace 618 + $ cat /sys/kernel/tracing/trace 619 619 ... 620 620 ip-2560 [007] ...1 318.460258: mlx5_esw_bridge_vlan_create: vid=1 flags=6 621 621 ··· 623 623 representor:: 624 624 625 625 $ echo mlx5:mlx5_esw_bridge_vlan_cleanup >> set_event 626 - $ cat /sys/kernel/debug/tracing/trace 626 + $ cat /sys/kernel/tracing/trace 627 627 ... 628 628 bridge-2582 [007] ...1 318.653496: mlx5_esw_bridge_vlan_cleanup: vid=2 flags=8 629 629 ··· 631 631 device:: 632 632 633 633 $ echo mlx5:mlx5_esw_bridge_vport_init >> set_event 634 - $ cat /sys/kernel/debug/tracing/trace 634 + $ cat /sys/kernel/tracing/trace 635 635 ... 636 636 ip-2560 [007] ...1 318.458915: mlx5_esw_bridge_vport_init: vport_num=1 637 637 ··· 639 639 device:: 640 640 641 641 $ echo mlx5:mlx5_esw_bridge_vport_cleanup >> set_event 642 - $ cat /sys/kernel/debug/tracing/trace 642 + $ cat /sys/kernel/tracing/trace 643 643 ... 644 644 ip-5387 [000] ...1 573713: mlx5_esw_bridge_vport_cleanup: vport_num=1 645 645 ··· 647 647 648 648 - mlx5_esw_vport_qos_create: trace creation of transmit scheduler arbiter for vport:: 649 649 650 - $ echo mlx5:mlx5_esw_vport_qos_create >> /sys/kernel/debug/tracing/set_event 651 - $ cat /sys/kernel/debug/tracing/trace 650 + $ echo mlx5:mlx5_esw_vport_qos_create >> /sys/kernel/tracing/set_event 651 + $ cat /sys/kernel/tracing/trace 652 652 ... 653 653 <...>-23496 [018] .... 73136.838831: mlx5_esw_vport_qos_create: (0000:82:00.0) vport=2 tsar_ix=4 bw_share=0, max_rate=0 group=000000007b576bb3 654 654 655 655 - mlx5_esw_vport_qos_config: trace configuration of transmit scheduler arbiter for vport:: 656 656 657 - $ echo mlx5:mlx5_esw_vport_qos_config >> /sys/kernel/debug/tracing/set_event 658 - $ cat /sys/kernel/debug/tracing/trace 657 + $ echo mlx5:mlx5_esw_vport_qos_config >> /sys/kernel/tracing/set_event 658 + $ cat /sys/kernel/tracing/trace 659 659 ... 660 660 <...>-26548 [023] .... 75754.223823: mlx5_esw_vport_qos_config: (0000:82:00.0) vport=1 tsar_ix=3 bw_share=34, max_rate=10000 group=000000007b576bb3 661 661 662 662 - mlx5_esw_vport_qos_destroy: trace deletion of transmit scheduler arbiter for vport:: 663 663 664 - $ echo mlx5:mlx5_esw_vport_qos_destroy >> /sys/kernel/debug/tracing/set_event 665 - $ cat /sys/kernel/debug/tracing/trace 664 + $ echo mlx5:mlx5_esw_vport_qos_destroy >> /sys/kernel/tracing/set_event 665 + $ cat /sys/kernel/tracing/trace 666 666 ... 667 667 <...>-27418 [004] .... 76546.680901: mlx5_esw_vport_qos_destroy: (0000:82:00.0) vport=1 tsar_ix=3 668 668 669 669 - mlx5_esw_group_qos_create: trace creation of transmit scheduler arbiter for rate group:: 670 670 671 - $ echo mlx5:mlx5_esw_group_qos_create >> /sys/kernel/debug/tracing/set_event 672 - $ cat /sys/kernel/debug/tracing/trace 671 + $ echo mlx5:mlx5_esw_group_qos_create >> /sys/kernel/tracing/set_event 672 + $ cat /sys/kernel/tracing/trace 673 673 ... 674 674 <...>-26578 [008] .... 75776.022112: mlx5_esw_group_qos_create: (0000:82:00.0) group=000000008dac63ea tsar_ix=5 675 675 676 676 - mlx5_esw_group_qos_config: trace configuration of transmit scheduler arbiter for rate group:: 677 677 678 - $ echo mlx5:mlx5_esw_group_qos_config >> /sys/kernel/debug/tracing/set_event 679 - $ cat /sys/kernel/debug/tracing/trace 678 + $ echo mlx5:mlx5_esw_group_qos_config >> /sys/kernel/tracing/set_event 679 + $ cat /sys/kernel/tracing/trace 680 680 ... 681 681 <...>-27303 [020] .... 76461.455356: mlx5_esw_group_qos_config: (0000:82:00.0) group=000000008dac63ea tsar_ix=5 bw_share=100 max_rate=20000 682 682 683 683 - mlx5_esw_group_qos_destroy: trace deletion of transmit scheduler arbiter for group:: 684 684 685 - $ echo mlx5:mlx5_esw_group_qos_destroy >> /sys/kernel/debug/tracing/set_event 686 - $ cat /sys/kernel/debug/tracing/trace 685 + $ echo mlx5:mlx5_esw_group_qos_destroy >> /sys/kernel/tracing/set_event 686 + $ cat /sys/kernel/tracing/trace 687 687 ... 688 688 <...>-27418 [006] .... 76547.187258: mlx5_esw_group_qos_destroy: (0000:82:00.0) group=000000007b576bb3 tsar_ix=1 689 689 ··· 691 691 692 692 - mlx5_sf_add: trace addition of the SF port:: 693 693 694 - $ echo mlx5:mlx5_sf_add >> /sys/kernel/debug/tracing/set_event 695 - $ cat /sys/kernel/debug/tracing/trace 694 + $ echo mlx5:mlx5_sf_add >> /sys/kernel/tracing/set_event 695 + $ cat /sys/kernel/tracing/trace 696 696 ... 697 697 devlink-9363 [031] ..... 24610.188722: mlx5_sf_add: (0000:06:00.0) port_index=32768 controller=0 hw_id=0x8000 sfnum=88 698 698 699 699 - mlx5_sf_free: trace freeing of the SF port:: 700 700 701 - $ echo mlx5:mlx5_sf_free >> /sys/kernel/debug/tracing/set_event 702 - $ cat /sys/kernel/debug/tracing/trace 701 + $ echo mlx5:mlx5_sf_free >> /sys/kernel/tracing/set_event 702 + $ cat /sys/kernel/tracing/trace 703 703 ... 704 704 devlink-9830 [038] ..... 26300.404749: mlx5_sf_free: (0000:06:00.0) port_index=32768 controller=0 hw_id=0x8000 705 705 706 706 - mlx5_sf_hwc_alloc: trace allocating of the hardware SF context:: 707 707 708 - $ echo mlx5:mlx5_sf_hwc_alloc >> /sys/kernel/debug/tracing/set_event 709 - $ cat /sys/kernel/debug/tracing/trace 708 + $ echo mlx5:mlx5_sf_hwc_alloc >> /sys/kernel/tracing/set_event 709 + $ cat /sys/kernel/tracing/trace 710 710 ... 711 711 devlink-9775 [031] ..... 26296.385259: mlx5_sf_hwc_alloc: (0000:06:00.0) controller=0 hw_id=0x8000 sfnum=88 712 712 713 713 - mlx5_sf_hwc_free: trace freeing of the hardware SF context:: 714 714 715 - $ echo mlx5:mlx5_sf_hwc_free >> /sys/kernel/debug/tracing/set_event 716 - $ cat /sys/kernel/debug/tracing/trace 715 + $ echo mlx5:mlx5_sf_hwc_free >> /sys/kernel/tracing/set_event 716 + $ cat /sys/kernel/tracing/trace 717 717 ... 718 718 kworker/u128:3-9093 [046] ..... 24625.365771: mlx5_sf_hwc_free: (0000:06:00.0) hw_id=0x8000 719 719 720 720 - mlx5_sf_hwc_deferred_free : trace deferred freeing of the hardware SF context:: 721 721 722 - $ echo mlx5:mlx5_sf_hwc_deferred_free >> /sys/kernel/debug/tracing/set_event 723 - $ cat /sys/kernel/debug/tracing/trace 722 + $ echo mlx5:mlx5_sf_hwc_deferred_free >> /sys/kernel/tracing/set_event 723 + $ cat /sys/kernel/tracing/trace 724 724 ... 725 725 devlink-9519 [046] ..... 24624.400271: mlx5_sf_hwc_deferred_free: (0000:06:00.0) hw_id=0x8000 726 726 727 727 - mlx5_sf_vhca_event: trace SF vhca event and state:: 728 728 729 - $ echo mlx5:mlx5_sf_vhca_event >> /sys/kernel/debug/tracing/set_event 730 - $ cat /sys/kernel/debug/tracing/trace 729 + $ echo mlx5:mlx5_sf_vhca_event >> /sys/kernel/tracing/set_event 730 + $ cat /sys/kernel/tracing/trace 731 731 ... 732 732 kworker/u128:3-9093 [046] ..... 24625.365525: mlx5_sf_vhca_event: (0000:06:00.0) hw_id=0x8000 sfnum=88 vhca_state=1 733 733 734 734 - mlx5_sf_dev_add : trace SF device add event:: 735 735 736 - $ echo mlx5:mlx5_sf_dev_add>> /sys/kernel/debug/tracing/set_event 737 - $ cat /sys/kernel/debug/tracing/trace 736 + $ echo mlx5:mlx5_sf_dev_add>> /sys/kernel/tracing/set_event 737 + $ cat /sys/kernel/tracing/trace 738 738 ... 739 739 kworker/u128:3-9093 [000] ..... 24616.524495: mlx5_sf_dev_add: (0000:06:00.0) sfdev=00000000fc5d96fd aux_id=4 hw_id=0x8000 sfnum=88 740 740 741 741 - mlx5_sf_dev_del : trace SF device delete event:: 742 742 743 - $ echo mlx5:mlx5_sf_dev_del >> /sys/kernel/debug/tracing/set_event 744 - $ cat /sys/kernel/debug/tracing/trace 743 + $ echo mlx5:mlx5_sf_dev_del >> /sys/kernel/tracing/set_event 744 + $ cat /sys/kernel/tracing/trace 745 745 ... 746 746 kworker/u128:3-9093 [044] ..... 24624.400749: mlx5_sf_dev_del: (0000:06:00.0) sfdev=00000000fc5d96fd aux_id=4 hw_id=0x8000 sfnum=88

+3 -3

Documentation/sound/hd-audio/notes.rst

··· 651 651 Enabling all tracepoints can be done like 652 652 :: 653 653 654 - # echo 1 > /sys/kernel/debug/tracing/events/hda/enable 654 + # echo 1 > /sys/kernel/tracing/events/hda/enable 655 655 656 656 then after some commands, you can traces from 657 - /sys/kernel/debug/tracing/trace file. For example, when you want to 657 + /sys/kernel/tracing/trace file. For example, when you want to 658 658 trace what codec command is sent, enable the tracepoint like: 659 659 :: 660 660 661 - # cat /sys/kernel/debug/tracing/trace 661 + # cat /sys/kernel/tracing/trace 662 662 # tracer: nop 663 663 # 664 664 # TASK-PID CPU# TIMESTAMP FUNCTION

+2 -2

Documentation/trace/events-msr.rst

··· 8 8 9 9 Available trace points: 10 10 11 - /sys/kernel/debug/tracing/events/msr/ 11 + /sys/kernel/tracing/events/msr/ 12 12 13 13 Trace MSR reads: 14 14 ··· 34 34 35 35 The trace data can be post processed with the postprocess/decode_msr.py script:: 36 36 37 - cat /sys/kernel/debug/tracing/trace | decode_msr.py /usr/src/linux/include/asm/msr-index.h 37 + cat /sys/kernel/tracing/trace | decode_msr.py /usr/src/linux/include/asm/msr-index.h 38 38 39 39 to add symbolic MSR names. 40 40

+3 -3

Documentation/trace/events-nmi.rst

··· 4 4 5 5 These events normally show up here: 6 6 7 - /sys/kernel/debug/tracing/events/nmi 7 + /sys/kernel/tracing/events/nmi 8 8 9 9 10 10 nmi_handler ··· 31 31 Note that the kernel's output is in milliseconds, but the input 32 32 to the filter is in nanoseconds! You can filter on 'delta_ns':: 33 33 34 - cd /sys/kernel/debug/tracing/events/nmi/nmi_handler 34 + cd /sys/kernel/tracing/events/nmi/nmi_handler 35 35 echo 'handler==0xffffffff81625600 && delta_ns>1000000' > filter 36 36 echo 1 > enable 37 37 38 38 Your output would then look like:: 39 39 40 - $ cat /sys/kernel/debug/tracing/trace_pipe 40 + $ cat /sys/kernel/tracing/trace_pipe 41 41 <idle>-0 [000] d.h3 505.397558: nmi_handler: perf_event_nmi_handler() delta_ns: 3236765 handled: 1 42 42 <idle>-0 [000] d.h3 505.805893: nmi_handler: perf_event_nmi_handler() delta_ns: 3174234 handled: 1 43 43 <idle>-0 [000] d.h3 506.158206: nmi_handler: perf_event_nmi_handler() delta_ns: 3084642 handled: 1

+37 -37

Documentation/trace/events.rst

··· 24 24 --------------------------------- 25 25 26 26 The events which are available for tracing can be found in the file 27 - /sys/kernel/debug/tracing/available_events. 27 + /sys/kernel/tracing/available_events. 28 28 29 29 To enable a particular event, such as 'sched_wakeup', simply echo it 30 - to /sys/kernel/debug/tracing/set_event. For example:: 30 + to /sys/kernel/tracing/set_event. For example:: 31 31 32 - # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event 32 + # echo sched_wakeup >> /sys/kernel/tracing/set_event 33 33 34 34 .. Note:: '>>' is necessary, otherwise it will firstly disable all the events. 35 35 36 36 To disable an event, echo the event name to the set_event file prefixed 37 37 with an exclamation point:: 38 38 39 - # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event 39 + # echo '!sched_wakeup' >> /sys/kernel/tracing/set_event 40 40 41 41 To disable all events, echo an empty line to the set_event file:: 42 42 43 - # echo > /sys/kernel/debug/tracing/set_event 43 + # echo > /sys/kernel/tracing/set_event 44 44 45 45 To enable all events, echo ``*:*`` or ``*:`` to the set_event file:: 46 46 47 - # echo *:* > /sys/kernel/debug/tracing/set_event 47 + # echo *:* > /sys/kernel/tracing/set_event 48 48 49 49 The events are organized into subsystems, such as ext4, irq, sched, 50 50 etc., and a full event name looks like this: <subsystem>:<event>. The ··· 53 53 ``<subsystem>:*``; for example, to enable all irq events, you can use the 54 54 command:: 55 55 56 - # echo 'irq:*' > /sys/kernel/debug/tracing/set_event 56 + # echo 'irq:*' > /sys/kernel/tracing/set_event 57 57 58 58 2.2 Via the 'enable' toggle 59 59 --------------------------- 60 60 61 - The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy 61 + The events available are also listed in /sys/kernel/tracing/events/ hierarchy 62 62 of directories. 63 63 64 64 To enable event 'sched_wakeup':: 65 65 66 - # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable 66 + # echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable 67 67 68 68 To disable it:: 69 69 70 - # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable 70 + # echo 0 > /sys/kernel/tracing/events/sched/sched_wakeup/enable 71 71 72 72 To enable all events in sched subsystem:: 73 73 74 - # echo 1 > /sys/kernel/debug/tracing/events/sched/enable 74 + # echo 1 > /sys/kernel/tracing/events/sched/enable 75 75 76 76 To enable all events:: 77 77 78 - # echo 1 > /sys/kernel/debug/tracing/events/enable 78 + # echo 1 > /sys/kernel/tracing/events/enable 79 79 80 80 When reading one of these enable files, there are four results: 81 81 ··· 126 126 For example, here's the information displayed for the 'sched_wakeup' 127 127 event:: 128 128 129 - # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format 129 + # cat /sys/kernel/tracing/events/sched/sched_wakeup/format 130 130 131 131 name: sched_wakeup 132 132 ID: 60 ··· 215 215 216 216 For example:: 217 217 218 - # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup 218 + # cd /sys/kernel/tracing/events/sched/sched_wakeup 219 219 # echo "common_preempt_count > 4" > filter 220 220 221 221 A slightly more involved example:: 222 222 223 - # cd /sys/kernel/debug/tracing/events/signal/signal_generate 223 + # cd /sys/kernel/tracing/events/signal/signal_generate 224 224 # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter 225 225 226 226 If there is an error in the expression, you'll get an 'Invalid 227 227 argument' error when setting it, and the erroneous string along with 228 228 an error message can be seen by looking at the filter e.g.:: 229 229 230 - # cd /sys/kernel/debug/tracing/events/signal/signal_generate 230 + # cd /sys/kernel/tracing/events/signal/signal_generate 231 231 # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter 232 232 -bash: echo: write error: Invalid argument 233 233 # cat filter ··· 277 277 278 278 Clear the filters on all events in the sched subsystem:: 279 279 280 - # cd /sys/kernel/debug/tracing/events/sched 280 + # cd /sys/kernel/tracing/events/sched 281 281 # echo 0 > filter 282 282 # cat sched_switch/filter 283 283 none ··· 287 287 Set a filter using only common fields for all events in the sched 288 288 subsystem (all events end up with the same filter):: 289 289 290 - # cd /sys/kernel/debug/tracing/events/sched 290 + # cd /sys/kernel/tracing/events/sched 291 291 # echo common_pid == 0 > filter 292 292 # cat sched_switch/filter 293 293 common_pid == 0 ··· 298 298 sched subsystem (all events but those that have a prev_pid field retain 299 299 their old filters):: 300 300 301 - # cd /sys/kernel/debug/tracing/events/sched 301 + # cd /sys/kernel/tracing/events/sched 302 302 # echo prev_pid == 0 > filter 303 303 # cat sched_switch/filter 304 304 prev_pid == 0 ··· 313 313 PID listed in the set_event_pid file. 314 314 :: 315 315 316 - # cd /sys/kernel/debug/tracing 316 + # cd /sys/kernel/tracing 317 317 # echo $$ > set_event_pid 318 318 # echo 1 > events/enable 319 319 ··· 409 409 specifies that this enablement happens only once:: 410 410 411 411 # echo 'enable_event:kmem:kmalloc:1' > \ 412 - /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 412 + /sys/kernel/tracing/events/syscalls/sys_enter_read/trigger 413 413 414 414 The following trigger causes kmalloc events to stop being traced 415 415 when a read system call exits. This disablement happens on every 416 416 read system call exit:: 417 417 418 418 # echo 'disable_event:kmem:kmalloc' > \ 419 - /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger 419 + /sys/kernel/tracing/events/syscalls/sys_exit_read/trigger 420 420 421 421 The format is:: 422 422 ··· 426 426 To remove the above commands:: 427 427 428 428 # echo '!enable_event:kmem:kmalloc:1' > \ 429 - /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 429 + /sys/kernel/tracing/events/syscalls/sys_enter_read/trigger 430 430 431 431 # echo '!disable_event:kmem:kmalloc' > \ 432 - /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger 432 + /sys/kernel/tracing/events/syscalls/sys_exit_read/trigger 433 433 434 434 Note that there can be any number of enable/disable_event triggers 435 435 per triggering event, but there can only be one trigger per ··· 448 448 kmalloc tracepoint is hit:: 449 449 450 450 # echo 'stacktrace' > \ 451 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 451 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 452 452 453 453 The following trigger dumps a stacktrace the first 5 times a kmalloc 454 454 request happens with a size >= 64K:: 455 455 456 456 # echo 'stacktrace:5 if bytes_req >= 65536' > \ 457 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 457 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 458 458 459 459 The format is:: 460 460 ··· 463 463 To remove the above commands:: 464 464 465 465 # echo '!stacktrace' > \ 466 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 466 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 467 467 468 468 # echo '!stacktrace:5 if bytes_req >= 65536' > \ 469 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 469 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 470 470 471 471 The latter can also be removed more simply by the following (without 472 472 the filter):: 473 473 474 474 # echo '!stacktrace:5' > \ 475 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 475 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 476 476 477 477 Note that there can be only one stacktrace trigger per triggering 478 478 event. ··· 488 488 capture those events when the trigger event occurred:: 489 489 490 490 # echo 'snapshot if nr_rq > 1' > \ 491 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 491 + /sys/kernel/tracing/events/block/block_unplug/trigger 492 492 493 493 To only snapshot once:: 494 494 495 495 # echo 'snapshot:1 if nr_rq > 1' > \ 496 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 496 + /sys/kernel/tracing/events/block/block_unplug/trigger 497 497 498 498 To remove the above commands:: 499 499 500 500 # echo '!snapshot if nr_rq > 1' > \ 501 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 501 + /sys/kernel/tracing/events/block/block_unplug/trigger 502 502 503 503 # echo '!snapshot:1 if nr_rq > 1' > \ 504 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 504 + /sys/kernel/tracing/events/block/block_unplug/trigger 505 505 506 506 Note that there can be only one snapshot trigger per triggering 507 507 event. ··· 519 519 trigger event:: 520 520 521 521 # echo 'traceoff:1 if nr_rq > 1' > \ 522 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 522 + /sys/kernel/tracing/events/block/block_unplug/trigger 523 523 524 524 To always disable tracing when nr_rq > 1:: 525 525 526 526 # echo 'traceoff if nr_rq > 1' > \ 527 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 527 + /sys/kernel/tracing/events/block/block_unplug/trigger 528 528 529 529 To remove the above commands:: 530 530 531 531 # echo '!traceoff:1 if nr_rq > 1' > \ 532 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 532 + /sys/kernel/tracing/events/block/block_unplug/trigger 533 533 534 534 # echo '!traceoff if nr_rq > 1' > \ 535 - /sys/kernel/debug/tracing/events/block/block_unplug/trigger 535 + /sys/kernel/tracing/events/block/block_unplug/trigger 536 536 537 537 Note that there can be only one traceon or traceoff trigger per 538 538 triggering event.

+3 -3

Documentation/trace/ftrace.rst

··· 830 830 The extended error information and usage takes the form shown in 831 831 this example:: 832 832 833 - # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger 833 + # echo xxx > /sys/kernel/tracing/events/sched/sched_wakeup/trigger 834 834 echo: write error: Invalid argument 835 835 836 - # cat /sys/kernel/debug/tracing/error_log 836 + # cat /sys/kernel/tracing/error_log 837 837 [ 5348.887237] location: error: Couldn't yyy: zzz 838 838 Command: xxx 839 839 ^ ··· 843 843 844 844 To clear the error log, echo the empty string into it:: 845 845 846 - # echo > /sys/kernel/debug/tracing/error_log 846 + # echo > /sys/kernel/tracing/error_log 847 847 848 848 Examples of using the tracer 849 849 ----------------------------

+6 -6

Documentation/trace/histogram-design.rst

··· 14 14 Note: All the ftrace histogram command examples assume the working 15 15 directory is the ftrace /tracing directory. For example:: 16 16 17 - # cd /sys/kernel/debug/tracing 17 + # cd /sys/kernel/tracing 18 18 19 19 Also, the histogram output displayed for those commands will be 20 20 generally be truncated - only enough to make the point is displayed. ··· 905 905 906 906 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ 907 907 onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid)' >> 908 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 908 + /sys/kernel/tracing/events/sched/sched_switch/trigger 909 909 910 910 The diagram for the sched_switch event is similar to previous examples 911 911 but shows the additional field_vars[] array for hist_data and shows ··· 1112 1112 wakeup_latency trace event. The next_pid and next_comm event fields 1113 1113 are automatically converted into field variables for this purpose:: 1114 1114 1115 - # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 1115 + # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/tracing/events/sched/sched_switch/trigger 1116 1116 1117 1117 The sched_waking hist_debug output shows the same data as in the 1118 1118 previous test example:: ··· 1305 1305 1306 1306 The commands below can be used to clean things up for the next test:: 1307 1307 1308 - # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 1308 + # echo '!hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_comm)' >> /sys/kernel/tracing/events/sched/sched_switch/trigger 1309 1309 1310 1310 # echo '!hist:keys=pid:ts0=common_timestamp.usecs' >> events/sched/sched_waking/trigger 1311 1311 ··· 1363 1363 1364 1364 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ 1365 1365 onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm)' >> 1366 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 1366 + /sys/kernel/tracing/events/sched/sched_switch/trigger 1367 1367 1368 1368 or:: 1369 1369 1370 1370 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ 1371 1371 onmax($wakeup_lat).snapshot()' >> 1372 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 1372 + /sys/kernel/tracing/events/sched/sched_switch/trigger 1373 1373 1374 1374 save() action field variable test 1375 1375 ---------------------------------

+95 -95

Documentation/trace/histogram.rst

··· 102 102 trigger, read its current contents, and then turn it off:: 103 103 104 104 # echo 'hist:keys=skbaddr.hex:vals=len' > \ 105 - /sys/kernel/debug/tracing/events/net/netif_rx/trigger 105 + /sys/kernel/tracing/events/net/netif_rx/trigger 106 106 107 - # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist 107 + # cat /sys/kernel/tracing/events/net/netif_rx/hist 108 108 109 109 # echo '!hist:keys=skbaddr.hex:vals=len' > \ 110 - /sys/kernel/debug/tracing/events/net/netif_rx/trigger 110 + /sys/kernel/tracing/events/net/netif_rx/trigger 111 111 112 112 The trigger file itself can be read to show the details of the 113 113 currently attached hist trigger. This information is also displayed ··· 169 169 aggregation on and off when conditions of interest are hit:: 170 170 171 171 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ 172 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 172 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 173 173 174 174 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ 175 - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 175 + /sys/kernel/tracing/events/sched/sched_process_exec/trigger 176 176 177 177 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ 178 - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 178 + /sys/kernel/tracing/events/sched/sched_process_exit/trigger 179 179 180 180 The above sets up an initially paused hist trigger which is unpaused 181 181 and starts aggregating events when a given program is executed, and ··· 218 218 event. The fields that can be used for the hist trigger are listed 219 219 in the kmalloc event's format file:: 220 220 221 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format 221 + # cat /sys/kernel/tracing/events/kmem/kmalloc/format 222 222 name: kmalloc 223 223 ID: 374 224 224 format: ··· 238 238 the kernel that made one or more calls to kmalloc:: 239 239 240 240 # echo 'hist:key=call_site:val=bytes_req.buckets=32' > \ 241 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 241 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 242 242 243 243 This tells the tracing system to create a 'hist' trigger using the 244 244 call_site field of the kmalloc event as the key for the table, which ··· 252 252 file in the kmalloc event's subdirectory (for readability, a number 253 253 of entries have been omitted):: 254 254 255 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 255 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 256 256 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] 257 257 258 258 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 ··· 292 292 the trigger info, which can also be displayed by reading the 293 293 'trigger' file:: 294 294 295 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 295 + # cat /sys/kernel/tracing/events/kmem/kmalloc/trigger 296 296 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] 297 297 298 298 At the end of the output are a few lines that display the overall ··· 323 323 command history and re-execute it with a '!' prepended:: 324 324 325 325 # echo '!hist:key=call_site:val=bytes_req' > \ 326 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 326 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 327 327 328 328 Finally, notice that the call_site as displayed in the output above 329 329 isn't really very useful. It's an address, but normally addresses ··· 331 331 value, simply append '.hex' to the field name in the trigger:: 332 332 333 333 # echo 'hist:key=call_site.hex:val=bytes_req' > \ 334 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 334 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 335 335 336 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 336 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 337 337 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] 338 338 339 339 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 ··· 376 376 trigger:: 377 377 378 378 # echo 'hist:key=call_site.sym:val=bytes_req' > \ 379 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 379 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 380 380 381 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 381 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 382 382 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] 383 383 384 384 { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 ··· 426 426 the 'sort' parameter, along with the 'descending' modifier:: 427 427 428 428 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ 429 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 429 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 430 430 431 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 431 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 432 432 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] 433 433 434 434 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 ··· 467 467 name, just use 'sym-offset' instead:: 468 468 469 469 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ 470 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 470 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 471 471 472 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 472 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 473 473 # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] 474 474 475 475 { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 ··· 506 506 allocated in a descending order:: 507 507 508 508 # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ 509 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 509 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 510 510 511 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 511 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 512 512 # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] 513 513 514 514 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 ··· 549 549 value 'stacktrace' for the key parameter:: 550 550 551 551 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ 552 - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 552 + /sys/kernel/tracing/events/kmem/kmalloc/trigger 553 553 554 554 The above trigger will use the kernel stack trace in effect when an 555 555 event is triggered as the key for the hash table. This allows the ··· 559 559 every callpath in the system that led up to a kmalloc (in this case 560 560 every callpath to a kmalloc for a kernel compile):: 561 561 562 - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 562 + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist 563 563 # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] 564 564 565 565 { stacktrace: ··· 658 658 keeps a per-process sum of total bytes read:: 659 659 660 660 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ 661 - /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 661 + /sys/kernel/tracing/events/syscalls/sys_enter_read/trigger 662 662 663 - # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist 663 + # cat /sys/kernel/tracing/events/syscalls/sys_enter_read/hist 664 664 # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] 665 665 666 666 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 ··· 699 699 counts for the system during the run:: 700 700 701 701 # echo 'hist:key=id.syscall:val=hitcount' > \ 702 - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 702 + /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger 703 703 704 - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 704 + # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist 705 705 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] 706 706 707 707 { id: sys_fsync [ 74] } hitcount: 1 ··· 753 753 hitcount sum as the secondary key:: 754 754 755 755 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ 756 - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 756 + /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger 757 757 758 - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 758 + # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist 759 759 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] 760 760 761 761 { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 ··· 803 803 can use that to filter out all the other syscalls:: 804 804 805 805 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ 806 - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 806 + /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger 807 807 808 - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 808 + # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist 809 809 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] 810 810 811 811 { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 ··· 846 846 each process:: 847 847 848 848 # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ 849 - /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger 849 + /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/trigger 850 850 851 - # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist 851 + # cat /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/hist 852 852 # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] 853 853 854 854 { common_pid: smbd [ 784], size: 4 } hitcount: 1 ··· 899 899 much smaller number, say 256:: 900 900 901 901 # echo 'hist:key=child_comm:val=hitcount:size=256' > \ 902 - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 902 + /sys/kernel/tracing/events/sched/sched_process_fork/trigger 903 903 904 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 904 + # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist 905 905 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] 906 906 907 907 { child_comm: dconf worker } hitcount: 1 ··· 935 935 displays as [paused]:: 936 936 937 937 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ 938 - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 938 + /sys/kernel/tracing/events/sched/sched_process_fork/trigger 939 939 940 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 940 + # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist 941 941 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] 942 942 943 943 { child_comm: dconf worker } hitcount: 1 ··· 972 972 again, and the data has changed:: 973 973 974 974 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ 975 - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 975 + /sys/kernel/tracing/events/sched/sched_process_fork/trigger 976 976 977 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 977 + # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist 978 978 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] 979 979 980 980 { child_comm: dconf worker } hitcount: 1 ··· 1026 1026 netif_receive_skb event:: 1027 1027 1028 1028 # echo 'hist:key=stacktrace:vals=len:pause' > \ 1029 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1029 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1030 1030 1031 1031 Next, we set up an 'enable_hist' trigger on the sched_process_exec 1032 1032 event, with an 'if filename==/usr/bin/wget' filter. The effect of ··· 1037 1037 hash table keyed on stacktrace:: 1038 1038 1039 1039 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ 1040 - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1040 + /sys/kernel/tracing/events/sched/sched_process_exec/trigger 1041 1041 1042 1042 The aggregation continues until the netif_receive_skb is paused 1043 1043 again, which is what the following disable_hist event does by ··· 1045 1045 filter 'comm==wget':: 1046 1046 1047 1047 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ 1048 - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1048 + /sys/kernel/tracing/events/sched/sched_process_exit/trigger 1049 1049 1050 1050 Whenever a process exits and the comm field of the disable_hist 1051 1051 trigger filter matches 'comm==wget', the netif_receive_skb hist ··· 1058 1058 1059 1059 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz 1060 1060 1061 - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist 1061 + # cat /sys/kernel/tracing/events/net/netif_receive_skb/hist 1062 1062 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] 1063 1063 1064 1064 { stacktrace: ··· 1142 1142 again, we can just clear the histogram first:: 1143 1143 1144 1144 # echo 'hist:key=stacktrace:vals=len:clear' >> \ 1145 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1145 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1146 1146 1147 1147 Just to verify that it is in fact cleared, here's what we now see in 1148 1148 the hist file:: 1149 1149 1150 - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist 1150 + # cat /sys/kernel/tracing/events/net/netif_receive_skb/hist 1151 1151 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] 1152 1152 1153 1153 Totals: ··· 1162 1162 sched_process_exit events as such:: 1163 1163 1164 1164 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ 1165 - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1165 + /sys/kernel/tracing/events/sched/sched_process_exec/trigger 1166 1166 1167 1167 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ 1168 - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1168 + /sys/kernel/tracing/events/sched/sched_process_exit/trigger 1169 1169 1170 1170 If you read the trigger files for the sched_process_exec and 1171 1171 sched_process_exit triggers, you should see two triggers for each: 1172 1172 one enabling/disabling the hist aggregation and the other 1173 1173 enabling/disabling the logging of events:: 1174 1174 1175 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1175 + # cat /sys/kernel/tracing/events/sched/sched_process_exec/trigger 1176 1176 enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget 1177 1177 enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget 1178 1178 1179 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1179 + # cat /sys/kernel/tracing/events/sched/sched_process_exit/trigger 1180 1180 enable_event:net:netif_receive_skb:unlimited if comm==wget 1181 1181 disable_hist:net:netif_receive_skb:unlimited if comm==wget 1182 1182 ··· 1192 1192 saw in the last run, but this time you should also see the 1193 1193 individual events in the trace file:: 1194 1194 1195 - # cat /sys/kernel/debug/tracing/trace 1195 + # cat /sys/kernel/tracing/trace 1196 1196 1197 1197 # tracer: nop 1198 1198 # ··· 1226 1226 other things:: 1227 1227 1228 1228 # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ 1229 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1229 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1230 1230 # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ 1231 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1231 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1232 1232 # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ 1233 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1233 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1234 1234 # echo 'hist:keys=skbaddr.hex:vals=len' >> \ 1235 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1235 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1236 1236 # echo 'hist:keys=len:vals=common_preempt_count' >> \ 1237 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1237 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1238 1238 1239 1239 The above set of commands create four triggers differing only in 1240 1240 their filters, along with a completely different though fairly ··· 1246 1246 Displaying the contents of the 'hist' file for the event shows the 1247 1247 contents of all five histograms:: 1248 1248 1249 - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist 1249 + # cat /sys/kernel/tracing/events/net/netif_receive_skb/hist 1250 1250 1251 1251 # event histogram 1252 1252 # ··· 1367 1367 field in the shared 'foo' histogram data:: 1368 1368 1369 1369 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ 1370 - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1370 + /sys/kernel/tracing/events/net/netif_receive_skb/trigger 1371 1371 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ 1372 - /sys/kernel/debug/tracing/events/net/netif_rx/trigger 1372 + /sys/kernel/tracing/events/net/netif_rx/trigger 1373 1373 1374 1374 You can see that they're updating common histogram data by reading 1375 1375 each event's hist files at the same time:: 1376 1376 1377 - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist; 1378 - cat /sys/kernel/debug/tracing/events/net/netif_rx/hist 1377 + # cat /sys/kernel/tracing/events/net/netif_receive_skb/hist; 1378 + cat /sys/kernel/tracing/events/net/netif_rx/hist 1379 1379 1380 1380 # event histogram 1381 1381 # ··· 1488 1488 couple of triggers named 'bar' using those fields:: 1489 1489 1490 1490 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ 1491 - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 1491 + /sys/kernel/tracing/events/sched/sched_process_fork/trigger 1492 1492 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ 1493 - /sys/kernel/debug/tracing/events/net/netif_rx/trigger 1493 + /sys/kernel/tracing/events/net/netif_rx/trigger 1494 1494 1495 1495 And displaying the output of either shows some interesting if 1496 1496 somewhat confusing output:: 1497 1497 1498 - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 1499 - # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist 1498 + # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist 1499 + # cat /sys/kernel/tracing/events/net/netif_rx/hist 1500 1500 1501 1501 # event histogram 1502 1502 # ··· 1826 1826 u64 lat; \ 1827 1827 pid_t pid; \ 1828 1828 int prio' >> \ 1829 - /sys/kernel/debug/tracing/synthetic_events 1829 + /sys/kernel/tracing/synthetic_events 1830 1830 1831 1831 Reading the tracing/synthetic_events file lists all the currently 1832 1832 defined synthetic events, in this case the event defined above:: 1833 1833 1834 - # cat /sys/kernel/debug/tracing/synthetic_events 1834 + # cat /sys/kernel/tracing/synthetic_events 1835 1835 wakeup_latency u64 lat; pid_t pid; int prio 1836 1836 1837 1837 An existing synthetic event definition can be removed by prepending 1838 1838 the command that defined it with a '!':: 1839 1839 1840 1840 # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \ 1841 - /sys/kernel/debug/tracing/synthetic_events 1841 + /sys/kernel/tracing/synthetic_events 1842 1842 1843 1843 At this point, there isn't yet an actual 'wakeup_latency' event 1844 1844 instantiated in the event subsystem - for this to happen, a 'hist ··· 1850 1850 The new event is created under the tracing/events/synthetic/ directory 1851 1851 and looks and behaves just like any other event:: 1852 1852 1853 - # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency 1853 + # ls /sys/kernel/tracing/events/synthetic/wakeup_latency 1854 1854 enable filter format hist id trigger 1855 1855 1856 1856 A histogram can now be defined for the new synthetic event:: 1857 1857 1858 1858 # echo 'hist:keys=pid,prio,lat.log2:sort=lat' >> \ 1859 - /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger 1859 + /sys/kernel/tracing/events/synthetic/wakeup_latency/trigger 1860 1860 1861 1861 The above shows the latency "lat" in a power of 2 grouping. 1862 1862 1863 1863 Like any other event, once a histogram is enabled for the event, the 1864 1864 output can be displayed by reading the event's 'hist' file. 1865 1865 1866 - # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist 1866 + # cat /sys/kernel/tracing/events/synthetic/wakeup_latency/hist 1867 1867 1868 1868 # event histogram 1869 1869 # ··· 1911 1911 the ".buckets" modifier and specify a size (in this case groups of 10). 1912 1912 1913 1913 # echo 'hist:keys=pid,prio,lat.buckets=10:sort=lat' >> \ 1914 - /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger 1914 + /sys/kernel/tracing/events/synthetic/wakeup_latency/trigger 1915 1915 1916 1916 # event histogram 1917 1917 # ··· 2039 2039 event:: 2040 2040 2041 2041 # echo 'wakeup_new_test pid_t pid' >> \ 2042 - /sys/kernel/debug/tracing/synthetic_events 2042 + /sys/kernel/tracing/synthetic_events 2043 2043 2044 - # cat /sys/kernel/debug/tracing/synthetic_events 2044 + # cat /sys/kernel/tracing/synthetic_events 2045 2045 wakeup_new_test pid_t pid 2046 2046 2047 2047 The following hist trigger both defines the missing testpid ··· 2052 2052 2053 2053 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ 2054 2054 wakeup_new_test($testpid) if comm=="cyclictest"' >> \ 2055 - /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger 2055 + /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger 2056 2056 2057 2057 Or, equivalently, using the 'trace' keyword syntax: 2058 2058 2059 2059 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ 2060 2060 trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ 2061 - /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger 2061 + /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger 2062 2062 2063 2063 Creating and displaying a histogram based on those events is now 2064 2064 just a matter of using the fields and new synthetic event in the 2065 2065 tracing/events/synthetic directory, as usual:: 2066 2066 2067 2067 # echo 'hist:keys=pid:sort=pid' >> \ 2068 - /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger 2068 + /sys/kernel/tracing/events/synthetic/wakeup_new_test/trigger 2069 2069 2070 2070 Running 'cyclictest' should cause wakeup_new events to generate 2071 2071 wakeup_new_test synthetic events which should result in histogram 2072 2072 output in the wakeup_new_test event's hist file:: 2073 2073 2074 - # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist 2074 + # cat /sys/kernel/tracing/events/synthetic/wakeup_new_test/hist 2075 2075 2076 2076 A more typical usage would be to use two events to calculate a 2077 2077 latency. The following example uses a set of hist triggers to ··· 2080 2080 First, we define a 'wakeup_latency' synthetic event:: 2081 2081 2082 2082 # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ 2083 - /sys/kernel/debug/tracing/synthetic_events 2083 + /sys/kernel/tracing/synthetic_events 2084 2084 2085 2085 Next, we specify that whenever we see a sched_waking event for a 2086 2086 cyclictest thread, save the timestamp in a 'ts0' variable:: 2087 2087 2088 2088 # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \ 2089 2089 if comm=="cyclictest"' >> \ 2090 - /sys/kernel/debug/tracing/events/sched/sched_waking/trigger 2090 + /sys/kernel/tracing/events/sched/sched_waking/trigger 2091 2091 2092 2092 Then, when the corresponding thread is actually scheduled onto the 2093 2093 CPU by a sched_switch event (saved_pid matches next_pid), calculate ··· 2097 2097 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\ 2098 2098 onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ 2099 2099 $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ 2100 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 2100 + /sys/kernel/tracing/events/sched/sched_switch/trigger 2101 2101 2102 2102 We also need to create a histogram on the wakeup_latency synthetic 2103 2103 event in order to aggregate the generated synthetic event data:: 2104 2104 2105 2105 # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ 2106 - /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger 2106 + /sys/kernel/tracing/events/synthetic/wakeup_latency/trigger 2107 2107 2108 2108 Finally, once we've run cyclictest to actually generate some 2109 2109 events, we can see the output by looking at the wakeup_latency 2110 2110 synthetic event's hist file:: 2111 2111 2112 - # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist 2112 + # cat /sys/kernel/tracing/events/synthetic/wakeup_latency/hist 2113 2113 2114 2114 - onmax(var).save(field,.. .) 2115 2115 ··· 2135 2135 2136 2136 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ 2137 2137 if comm=="cyclictest"' >> \ 2138 - /sys/kernel/debug/tracing/events/sched/sched_waking/trigger 2138 + /sys/kernel/tracing/events/sched/sched_waking/trigger 2139 2139 2140 2140 # echo 'hist:keys=next_pid:\ 2141 2141 wakeup_lat=common_timestamp.usecs-$ts0:\ 2142 2142 onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ 2143 2143 if next_comm=="cyclictest"' >> \ 2144 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 2144 + /sys/kernel/tracing/events/sched/sched_switch/trigger 2145 2145 2146 2146 When the histogram is displayed, the max value and the saved 2147 2147 values corresponding to the max are displayed following the rest 2148 2148 of the fields:: 2149 2149 2150 - # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist 2150 + # cat /sys/kernel/tracing/events/sched/sched_switch/hist 2151 2151 { next_pid: 2255 } hitcount: 239 2152 2152 common_timestamp-ts0: 0 2153 2153 max: 27 ··· 2193 2193 the scheduler events are also enabled, which are the events that 2194 2194 will show up in the snapshot when it is taken at some point: 2195 2195 2196 - # echo 1 > /sys/kernel/debug/tracing/events/sched/enable 2196 + # echo 1 > /sys/kernel/tracing/events/sched/enable 2197 2197 2198 2198 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ 2199 2199 if comm=="cyclictest"' >> \ 2200 - /sys/kernel/debug/tracing/events/sched/sched_waking/trigger 2200 + /sys/kernel/tracing/events/sched/sched_waking/trigger 2201 2201 2202 2202 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ 2203 2203 onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ 2204 2204 prev_comm):onmax($wakeup_lat).snapshot() \ 2205 2205 if next_comm=="cyclictest"' >> \ 2206 - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger 2206 + /sys/kernel/tracing/events/sched/sched_switch/trigger 2207 2207 2208 2208 When the histogram is displayed, for each bucket the max value 2209 2209 and the saved values corresponding to the max are displayed ··· 2212 2212 If a snapshot was taken, there is also a message indicating that, 2213 2213 along with the value and event that triggered the global maximum: 2214 2214 2215 - # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist 2215 + # cat /sys/kernel/tracing/events/sched/sched_switch/hist 2216 2216 { next_pid: 2101 } hitcount: 200 2217 2217 max: 52 next_prio: 120 next_comm: cyclictest \ 2218 2218 prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 ··· 2247 2247 sched_switch events, which should match the time displayed in the 2248 2248 global maximum):: 2249 2249 2250 - # cat /sys/kernel/debug/tracing/snapshot 2250 + # cat /sys/kernel/tracing/snapshot 2251 2251 2252 2252 <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 2253 2253 <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 ··· 2312 2312 enabled, which are the events that will show up in the snapshot 2313 2313 when it is taken at some point: 2314 2314 2315 - # echo 1 > /sys/kernel/debug/tracing/events/sched/enable 2316 - # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable 2315 + # echo 1 > /sys/kernel/tracing/events/sched/enable 2316 + # echo 1 > /sys/kernel/tracing/events/tcp/enable 2317 2317 2318 2318 # echo 'hist:keys=dport:cwnd=snd_cwnd: \ 2319 2319 onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ 2320 2320 onchange($cwnd).snapshot()' >> \ 2321 - /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger 2321 + /sys/kernel/tracing/events/tcp/tcp_probe/trigger 2322 2322 2323 2323 When the histogram is displayed, for each bucket the tracked value 2324 2324 and the saved values corresponding to that value are displayed ··· 2327 2327 If a snapshot was taken, there is also a message indicating that, 2328 2328 along with the value and event that triggered the snapshot:: 2329 2329 2330 - # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist 2330 + # cat /sys/kernel/tracing/events/tcp/tcp_probe/hist 2331 2331 2332 2332 { dport: 1521 } hitcount: 8 2333 2333 changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 ··· 2361 2361 And finally, looking at the snapshot data should show at or near 2362 2362 the end the event that triggered the snapshot:: 2363 2363 2364 - # cat /sys/kernel/debug/tracing/snapshot 2364 + # cat /sys/kernel/tracing/snapshot 2365 2365 2366 2366 gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] 2367 2367 kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120

+13 -13

Documentation/trace/kprobetrace.rst

··· 17 17 18 18 Similar to the event tracer, this doesn't need to be activated via 19 19 current_tracer. Instead of that, add probe points via 20 - /sys/kernel/debug/tracing/kprobe_events, and enable it via 21 - /sys/kernel/debug/tracing/events/kprobes/<EVENT>/enable. 20 + /sys/kernel/tracing/kprobe_events, and enable it via 21 + /sys/kernel/tracing/events/kprobes/<EVENT>/enable. 22 22 23 - You can also use /sys/kernel/debug/tracing/dynamic_events instead of 23 + You can also use /sys/kernel/tracing/dynamic_events instead of 24 24 kprobe_events. That interface will provide unified access to other 25 25 dynamic events too. 26 26 ··· 153 153 Event Profiling 154 154 --------------- 155 155 You can check the total number of probe hits and probe miss-hits via 156 - /sys/kernel/debug/tracing/kprobe_profile. 156 + /sys/kernel/tracing/kprobe_profile. 157 157 The first column is event name, the second is the number of probe hits, 158 158 the third is the number of probe miss-hits. 159 159 ··· 177 177 To add a probe as a new event, write a new definition to kprobe_events 178 178 as below:: 179 179 180 - echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/debug/tracing/kprobe_events 180 + echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/tracing/kprobe_events 181 181 182 182 This sets a kprobe on the top of do_sys_open() function with recording 183 183 1st to 4th arguments as "myprobe" event. Note, which register/stack entry is ··· 187 187 As this example shows, users can choose more familiar names for each arguments. 188 188 :: 189 189 190 - echo 'r:myretprobe do_sys_open $retval' >> /sys/kernel/debug/tracing/kprobe_events 190 + echo 'r:myretprobe do_sys_open $retval' >> /sys/kernel/tracing/kprobe_events 191 191 192 192 This sets a kretprobe on the return point of do_sys_open() function with 193 193 recording return value as "myretprobe" event. 194 194 You can see the format of these events via 195 - /sys/kernel/debug/tracing/events/kprobes/<EVENT>/format. 195 + /sys/kernel/tracing/events/kprobes/<EVENT>/format. 196 196 :: 197 197 198 - cat /sys/kernel/debug/tracing/events/kprobes/myprobe/format 198 + cat /sys/kernel/tracing/events/kprobes/myprobe/format 199 199 name: myprobe 200 200 ID: 780 201 201 format: ··· 218 218 You can see that the event has 4 arguments as in the expressions you specified. 219 219 :: 220 220 221 - echo > /sys/kernel/debug/tracing/kprobe_events 221 + echo > /sys/kernel/tracing/kprobe_events 222 222 223 223 This clears all probe points. 224 224 ··· 233 233 events, you need to enable it. 234 234 :: 235 235 236 - echo 1 > /sys/kernel/debug/tracing/events/kprobes/myprobe/enable 237 - echo 1 > /sys/kernel/debug/tracing/events/kprobes/myretprobe/enable 236 + echo 1 > /sys/kernel/tracing/events/kprobes/myprobe/enable 237 + echo 1 > /sys/kernel/tracing/events/kprobes/myretprobe/enable 238 238 239 239 Use the following command to start tracing in an interval. 240 240 :: ··· 243 243 Open something... 244 244 # echo 0 > tracing_on 245 245 246 - And you can see the traced information via /sys/kernel/debug/tracing/trace. 246 + And you can see the traced information via /sys/kernel/tracing/trace. 247 247 :: 248 248 249 - cat /sys/kernel/debug/tracing/trace 249 + cat /sys/kernel/tracing/trace 250 250 # tracer: nop 251 251 # 252 252 # TASK-PID CPU# TIMESTAMP FUNCTION

+10 -10

Documentation/trace/mmiotrace.rst

··· 36 36 :: 37 37 38 38 $ mount -t debugfs debugfs /sys/kernel/debug 39 - $ echo mmiotrace > /sys/kernel/debug/tracing/current_tracer 40 - $ cat /sys/kernel/debug/tracing/trace_pipe > mydump.txt & 39 + $ echo mmiotrace > /sys/kernel/tracing/current_tracer 40 + $ cat /sys/kernel/tracing/trace_pipe > mydump.txt & 41 41 Start X or whatever. 42 - $ echo "X is up" > /sys/kernel/debug/tracing/trace_marker 43 - $ echo nop > /sys/kernel/debug/tracing/current_tracer 42 + $ echo "X is up" > /sys/kernel/tracing/trace_marker 43 + $ echo nop > /sys/kernel/tracing/current_tracer 44 44 Check for lost events. 45 45 46 46 ··· 56 56 57 57 Activate mmiotrace (requires root privileges):: 58 58 59 - $ echo mmiotrace > /sys/kernel/debug/tracing/current_tracer 59 + $ echo mmiotrace > /sys/kernel/tracing/current_tracer 60 60 61 61 Start storing the trace:: 62 62 63 - $ cat /sys/kernel/debug/tracing/trace_pipe > mydump.txt & 63 + $ cat /sys/kernel/tracing/trace_pipe > mydump.txt & 64 64 65 65 The 'cat' process should stay running (sleeping) in the background. 66 66 ··· 68 68 accesses to areas that are ioremapped while mmiotrace is active. 69 69 70 70 During tracing you can place comments (markers) into the trace by 71 - $ echo "X is up" > /sys/kernel/debug/tracing/trace_marker 71 + $ echo "X is up" > /sys/kernel/tracing/trace_marker 72 72 This makes it easier to see which part of the (huge) trace corresponds to 73 73 which action. It is recommended to place descriptive markers about what you 74 74 do. 75 75 76 76 Shut down mmiotrace (requires root privileges):: 77 77 78 - $ echo nop > /sys/kernel/debug/tracing/current_tracer 78 + $ echo nop > /sys/kernel/tracing/current_tracer 79 79 80 80 The 'cat' process exits. If it does not, kill it by issuing 'fg' command and 81 81 pressing ctrl+c. ··· 93 93 try again. Buffers are enlarged by first seeing how large the current buffers 94 94 are:: 95 95 96 - $ cat /sys/kernel/debug/tracing/buffer_size_kb 96 + $ cat /sys/kernel/tracing/buffer_size_kb 97 97 98 98 gives you a number. Approximately double this number and write it back, for 99 99 instance:: 100 100 101 - $ echo 128000 > /sys/kernel/debug/tracing/buffer_size_kb 101 + $ echo 128000 > /sys/kernel/tracing/buffer_size_kb 102 102 103 103 Then start again from the top. 104 104

+2 -2

Documentation/trace/postprocess/trace-pagealloc-postprocess.pl

··· 4 4 # to extract some high-level information on what is going on. The accuracy of the parser 5 5 # may vary considerably 6 6 # 7 - # Example usage: trace-pagealloc-postprocess.pl < /sys/kernel/debug/tracing/trace_pipe 7 + # Example usage: trace-pagealloc-postprocess.pl < /sys/kernel/tracing/trace_pipe 8 8 # other options 9 9 # --prepend-parent Report on the parent proc and PID 10 10 # --read-procstat If the trace lacks process info, get it from /proc ··· 94 94 my $regex; 95 95 96 96 # Read the event format or use the default 97 - if (!open (FORMAT, "/sys/kernel/debug/tracing/events/$event/format")) { 97 + if (!open (FORMAT, "/sys/kernel/tracing/events/$event/format")) { 98 98 $regex = $default; 99 99 } else { 100 100 my $line;

+2 -2

Documentation/trace/postprocess/trace-vmscan-postprocess.pl

··· 3 3 # page reclaim. It makes an attempt to extract some high-level information on 4 4 # what is going on. The accuracy of the parser may vary 5 5 # 6 - # Example usage: trace-vmscan-postprocess.pl < /sys/kernel/debug/tracing/trace_pipe 6 + # Example usage: trace-vmscan-postprocess.pl < /sys/kernel/tracing/trace_pipe 7 7 # other options 8 8 # --read-procstat If the trace lacks process info, get it from /proc 9 9 # --ignore-pid Aggregate processes of the same name together ··· 140 140 my $regex; 141 141 142 142 # Read the event format or use the default 143 - if (!open (FORMAT, "/sys/kernel/debug/tracing/events/$event/format")) { 143 + if (!open (FORMAT, "/sys/kernel/tracing/events/$event/format")) { 144 144 print("WARNING: Event $event format string not found\n"); 145 145 return $default; 146 146 } else {

+4 -4

Documentation/trace/tracepoint-analysis.rst

··· 26 26 2.1 Standard Utilities 27 27 ---------------------- 28 28 29 - All possible events are visible from /sys/kernel/debug/tracing/events. Simply 29 + All possible events are visible from /sys/kernel/tracing/events. Simply 30 30 calling:: 31 31 32 - $ find /sys/kernel/debug/tracing/events -type d 32 + $ find /sys/kernel/tracing/events -type d 33 33 34 34 will give a fair indication of the number of events available. 35 35 ··· 59 59 can be enabled system-wide. A short example of enabling all events related 60 60 to page allocation would look something like:: 61 61 62 - $ for i in `find /sys/kernel/debug/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done 62 + $ for i in `find /sys/kernel/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done 63 63 64 64 3.2 System-Wide Event Enabling with SystemTap 65 65 --------------------------------------------- ··· 189 189 ============================================ 190 190 191 191 When events are enabled the events that are triggering can be read from 192 - /sys/kernel/debug/tracing/trace_pipe in human-readable format although binary 192 + /sys/kernel/tracing/trace_pipe in human-readable format although binary 193 193 options exist as well. By post-processing the output, further information can 194 194 be gathered on-line as appropriate. Examples of post-processing might include 195 195

+11 -11

Documentation/trace/uprobetracer.rst

··· 12 12 13 13 Similar to the kprobe-event tracer, this doesn't need to be activated via 14 14 current_tracer. Instead of that, add probe points via 15 - /sys/kernel/debug/tracing/uprobe_events, and enable it via 16 - /sys/kernel/debug/tracing/events/uprobes/<EVENT>/enable. 15 + /sys/kernel/tracing/uprobe_events, and enable it via 16 + /sys/kernel/tracing/events/uprobes/<EVENT>/enable. 17 17 18 18 However unlike kprobe-event tracer, the uprobe event interface expects the 19 19 user to calculate the offset of the probepoint in the object. 20 20 21 - You can also use /sys/kernel/debug/tracing/dynamic_events instead of 21 + You can also use /sys/kernel/tracing/dynamic_events instead of 22 22 uprobe_events. That interface will provide unified access to other 23 23 dynamic events too. 24 24 ··· 79 79 Event Profiling 80 80 --------------- 81 81 You can check the total number of probe hits per event via 82 - /sys/kernel/debug/tracing/uprobe_profile. The first column is the filename, 82 + /sys/kernel/tracing/uprobe_profile. The first column is the filename, 83 83 the second is the event name, the third is the number of probe hits. 84 84 85 85 Usage examples ··· 87 87 * Add a probe as a new uprobe event, write a new definition to uprobe_events 88 88 as below (sets a uprobe at an offset of 0x4245c0 in the executable /bin/bash):: 89 89 90 - echo 'p /bin/bash:0x4245c0' > /sys/kernel/debug/tracing/uprobe_events 90 + echo 'p /bin/bash:0x4245c0' > /sys/kernel/tracing/uprobe_events 91 91 92 92 * Add a probe as a new uretprobe event:: 93 93 94 - echo 'r /bin/bash:0x4245c0' > /sys/kernel/debug/tracing/uprobe_events 94 + echo 'r /bin/bash:0x4245c0' > /sys/kernel/tracing/uprobe_events 95 95 96 96 * Unset registered event:: 97 97 98 - echo '-:p_bash_0x4245c0' >> /sys/kernel/debug/tracing/uprobe_events 98 + echo '-:p_bash_0x4245c0' >> /sys/kernel/tracing/uprobe_events 99 99 100 100 * Print out the events that are registered:: 101 101 102 - cat /sys/kernel/debug/tracing/uprobe_events 102 + cat /sys/kernel/tracing/uprobe_events 103 103 104 104 * Clear all events:: 105 105 106 - echo > /sys/kernel/debug/tracing/uprobe_events 106 + echo > /sys/kernel/tracing/uprobe_events 107 107 108 108 Following example shows how to dump the instruction pointer and %ax register 109 109 at the probed text address. Probe zfree function in /bin/zsh:: 110 110 111 - # cd /sys/kernel/debug/tracing/ 111 + # cd /sys/kernel/tracing/ 112 112 # cat /proc/`pgrep zsh`/maps | grep /bin/zsh | grep r-xp 113 113 00400000-0048a000 r-xp 00000000 08:03 130904 /bin/zsh 114 114 # objdump -T /bin/zsh | grep -w zfree ··· 168 168 169 169 # echo 0 > events/uprobes/enable 170 170 171 - And you can see the traced information via /sys/kernel/debug/tracing/trace. 171 + And you can see the traced information via /sys/kernel/tracing/trace. 172 172 :: 173 173 174 174 # cat trace

+9 -9

Documentation/trace/user_events.rst

··· 11 11 To enable this feature, build your kernel with CONFIG_USER_EVENTS=y. 12 12 13 13 Programs can view status of the events via 14 - /sys/kernel/debug/tracing/user_events_status and can both register and write 15 - data out via /sys/kernel/debug/tracing/user_events_data. 14 + /sys/kernel/tracing/user_events_status and can both register and write 15 + data out via /sys/kernel/tracing/user_events_data. 16 16 17 - Programs can also use /sys/kernel/debug/tracing/dynamic_events to register and 17 + Programs can also use /sys/kernel/tracing/dynamic_events to register and 18 18 delete user based events via the u: prefix. The format of the command to 19 19 dynamic_events is the same as the ioctl with the u: prefix applied. 20 20 ··· 22 22 tools that can read trace_events (such as ftrace and perf). The registration 23 23 process gives back two ints to the program for each event. The first int is 24 24 the status bit. This describes which bit in little-endian format in the 25 - /sys/kernel/debug/tracing/user_events_status file represents this event. The 25 + /sys/kernel/tracing/user_events_status file represents this event. The 26 26 second int is the write index which describes the data when a write() or 27 - writev() is called on the /sys/kernel/debug/tracing/user_events_data file. 27 + writev() is called on the /sys/kernel/tracing/user_events_data file. 28 28 29 29 The structures referenced in this document are contained within the 30 30 /include/uapi/linux/user_events.h file in the source tree. ··· 35 35 Registering 36 36 ----------- 37 37 Registering within a user process is done via ioctl() out to the 38 - /sys/kernel/debug/tracing/user_events_data file. The command to issue is 38 + /sys/kernel/tracing/user_events_data file. The command to issue is 39 39 DIAG_IOCSREG. 40 40 41 41 This command takes a packed struct user_reg as an argument:: ··· 54 54 55 55 User based events show up under tracefs like any other event under the 56 56 subsystem named "user_events". This means tools that wish to attach to the 57 - events need to use /sys/kernel/debug/tracing/events/user_events/[name]/enable 57 + events need to use /sys/kernel/tracing/events/user_events/[name]/enable 58 58 or perf record -e user_events:[name] when attaching/recording. 59 59 60 60 **NOTE:** *The write_index returned is only valid for the FD that was used* ··· 96 96 Deleting 97 97 ----------- 98 98 Deleting an event from within a user process is done via ioctl() out to the 99 - /sys/kernel/debug/tracing/user_events_data file. The command to issue is 99 + /sys/kernel/tracing/user_events_data file. The command to issue is 100 100 DIAG_IOCSDEL. 101 101 102 102 This command only requires a single string specifying the event to delete by ··· 110 110 in realtime. This allows user programs to only incur the cost of the write() or 111 111 writev() calls when something is actively attached to the event. 112 112 113 - User programs call mmap() on /sys/kernel/debug/tracing/user_events_status to 113 + User programs call mmap() on /sys/kernel/tracing/user_events_status to 114 114 check the status for each event that is registered. The bit to check in the 115 115 file is given back after the register ioctl() via user_reg.status_bit. The bit 116 116 is always in little-endian format. Programs can check if the bit is set either

+2 -2

Documentation/translations/zh_CN/core-api/workqueue.rst

··· 313 313 314 314 第一个可以用追踪的方式进行跟踪: :: 315 315 316 - $ echo workqueue:workqueue_queue_work > /sys/kernel/debug/tracing/set_event 317 - $ cat /sys/kernel/debug/tracing/trace_pipe > out.txt 316 + $ echo workqueue:workqueue_queue_work > /sys/kernel/tracing/set_event 317 + $ cat /sys/kernel/tracing/trace_pipe > out.txt 318 318 (wait a few secs) 319 319 320 320 如果有什么东西在工作队列上忙着做循环，它就会主导输出，可以用工作项函数确定违规者。

+9 -9

Documentation/x86/resctrl.rst

··· 608 608 visualize this data with a histogram that is available if CONFIG_HIST_TRIGGERS 609 609 is set:: 610 610 611 - # :> /sys/kernel/debug/tracing/trace 612 - # echo 'hist:keys=latency' > /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_mem_latency/trigger 613 - # echo 1 > /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_mem_latency/enable 611 + # :> /sys/kernel/tracing/trace 612 + # echo 'hist:keys=latency' > /sys/kernel/tracing/events/resctrl/pseudo_lock_mem_latency/trigger 613 + # echo 1 > /sys/kernel/tracing/events/resctrl/pseudo_lock_mem_latency/enable 614 614 # echo 1 > /sys/kernel/debug/resctrl/newlock/pseudo_lock_measure 615 - # echo 0 > /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_mem_latency/enable 616 - # cat /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_mem_latency/hist 615 + # echo 0 > /sys/kernel/tracing/events/resctrl/pseudo_lock_mem_latency/enable 616 + # cat /sys/kernel/tracing/events/resctrl/pseudo_lock_mem_latency/hist 617 617 618 618 # event histogram 619 619 # ··· 642 642 and misses using the platform's precision counters. 643 643 :: 644 644 645 - # :> /sys/kernel/debug/tracing/trace 646 - # echo 1 > /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_l2/enable 645 + # :> /sys/kernel/tracing/trace 646 + # echo 1 > /sys/kernel/tracing/events/resctrl/pseudo_lock_l2/enable 647 647 # echo 2 > /sys/kernel/debug/resctrl/newlock/pseudo_lock_measure 648 - # echo 0 > /sys/kernel/debug/tracing/events/resctrl/pseudo_lock_l2/enable 649 - # cat /sys/kernel/debug/tracing/trace 648 + # echo 0 > /sys/kernel/tracing/events/resctrl/pseudo_lock_l2/enable 649 + # cat /sys/kernel/tracing/trace 650 650 651 651 # tracer: nop 652 652 #