ftrace.rst 130 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600160116021603160416051606160716081609161016111612161316141615161616171618161916201621162216231624162516261627162816291630163116321633163416351636163716381639164016411642164316441645164616471648164916501651165216531654165516561657165816591660166116621663166416651666166716681669167016711672167316741675167616771678167916801681168216831684168516861687168816891690169116921693169416951696169716981699170017011702170317041705170617071708170917101711171217131714171517161717171817191720172117221723172417251726172717281729173017311732173317341735173617371738173917401741174217431744174517461747174817491750175117521753175417551756175717581759176017611762176317641765176617671768176917701771177217731774177517761777177817791780178117821783178417851786178717881789179017911792179317941795179617971798179918001801180218031804180518061807180818091810181118121813181418151816181718181819182018211822182318241825182618271828182918301831183218331834183518361837183818391840184118421843184418451846184718481849185018511852185318541855185618571858185918601861186218631864186518661867186818691870187118721873187418751876187718781879188018811882188318841885188618871888188918901891189218931894189518961897189818991900190119021903190419051906190719081909191019111912191319141915191619171918191919201921192219231924192519261927192819291930193119321933193419351936193719381939194019411942194319441945194619471948194919501951195219531954195519561957195819591960196119621963196419651966196719681969197019711972197319741975197619771978197919801981198219831984198519861987198819891990199119921993199419951996199719981999200020012002200320042005200620072008200920102011201220132014201520162017201820192020202120222023202420252026202720282029203020312032203320342035203620372038203920402041204220432044204520462047204820492050205120522053205420552056205720582059206020612062206320642065206620672068206920702071207220732074207520762077207820792080208120822083208420852086208720882089209020912092209320942095209620972098209921002101210221032104210521062107210821092110211121122113211421152116211721182119212021212122212321242125212621272128212921302131213221332134213521362137213821392140214121422143214421452146214721482149215021512152215321542155215621572158215921602161216221632164216521662167216821692170217121722173217421752176217721782179218021812182218321842185218621872188218921902191219221932194219521962197219821992200220122022203220422052206220722082209221022112212221322142215221622172218221922202221222222232224222522262227222822292230223122322233223422352236223722382239224022412242224322442245224622472248224922502251225222532254225522562257225822592260226122622263226422652266226722682269227022712272227322742275227622772278227922802281228222832284228522862287228822892290229122922293229422952296229722982299230023012302230323042305230623072308230923102311231223132314231523162317231823192320232123222323232423252326232723282329233023312332233323342335233623372338233923402341234223432344234523462347234823492350235123522353235423552356235723582359236023612362236323642365236623672368236923702371237223732374237523762377237823792380238123822383238423852386238723882389239023912392239323942395239623972398239924002401240224032404240524062407240824092410241124122413241424152416241724182419242024212422242324242425242624272428242924302431243224332434243524362437243824392440244124422443244424452446244724482449245024512452245324542455245624572458245924602461246224632464246524662467246824692470247124722473247424752476247724782479248024812482248324842485248624872488248924902491249224932494249524962497249824992500250125022503250425052506250725082509251025112512251325142515251625172518251925202521252225232524252525262527252825292530253125322533253425352536253725382539254025412542254325442545254625472548254925502551255225532554255525562557255825592560256125622563256425652566256725682569257025712572257325742575257625772578257925802581258225832584258525862587258825892590259125922593259425952596259725982599260026012602260326042605260626072608260926102611261226132614261526162617261826192620262126222623262426252626262726282629263026312632263326342635263626372638263926402641264226432644264526462647264826492650265126522653265426552656265726582659266026612662266326642665266626672668266926702671267226732674267526762677267826792680268126822683268426852686268726882689269026912692269326942695269626972698269927002701270227032704270527062707270827092710271127122713271427152716271727182719272027212722272327242725272627272728272927302731273227332734273527362737273827392740274127422743274427452746274727482749275027512752275327542755275627572758275927602761276227632764276527662767276827692770277127722773277427752776277727782779278027812782278327842785278627872788278927902791279227932794279527962797279827992800280128022803280428052806280728082809281028112812281328142815281628172818281928202821282228232824282528262827282828292830283128322833283428352836283728382839284028412842284328442845284628472848284928502851285228532854285528562857285828592860286128622863286428652866286728682869287028712872287328742875287628772878287928802881288228832884288528862887288828892890289128922893289428952896289728982899290029012902290329042905290629072908290929102911291229132914291529162917291829192920292129222923292429252926292729282929293029312932293329342935293629372938293929402941294229432944294529462947294829492950295129522953295429552956295729582959296029612962296329642965296629672968296929702971297229732974297529762977297829792980298129822983298429852986298729882989299029912992299329942995299629972998299930003001300230033004300530063007300830093010301130123013301430153016301730183019302030213022302330243025302630273028302930303031303230333034303530363037303830393040304130423043304430453046304730483049305030513052305330543055305630573058305930603061306230633064306530663067306830693070307130723073307430753076307730783079308030813082308330843085308630873088308930903091309230933094309530963097309830993100310131023103310431053106310731083109311031113112311331143115311631173118311931203121312231233124312531263127312831293130313131323133313431353136313731383139314031413142314331443145314631473148314931503151315231533154315531563157315831593160316131623163316431653166316731683169317031713172317331743175317631773178317931803181318231833184318531863187318831893190319131923193319431953196319731983199320032013202320332043205320632073208320932103211321232133214321532163217321832193220322132223223322432253226322732283229323032313232323332343235323632373238323932403241324232433244324532463247324832493250325132523253325432553256325732583259326032613262326332643265326632673268326932703271327232733274327532763277327832793280328132823283328432853286328732883289329032913292329332943295329632973298329933003301330233033304330533063307330833093310331133123313331433153316331733183319332033213322332333243325332633273328332933303331333233333334333533363337333833393340334133423343334433453346334733483349335033513352335333543355335633573358335933603361336233633364336533663367336833693370337133723373337433753376337733783379338033813382338333843385338633873388338933903391339233933394339533963397339833993400340134023403340434053406340734083409341034113412341334143415341634173418341934203421342234233424342534263427342834293430343134323433343434353436343734383439344034413442344334443445344634473448344934503451345234533454345534563457345834593460346134623463346434653466346734683469347034713472347334743475347634773478347934803481348234833484348534863487348834893490349134923493349434953496349734983499350035013502350335043505350635073508350935103511351235133514351535163517351835193520352135223523352435253526352735283529353035313532353335343535353635373538353935403541354235433544354535463547354835493550355135523553355435553556
  1. ========================
  2. ftrace - Function Tracer
  3. ========================
  4. Copyright 2008 Red Hat Inc.
  5. :Author: Steven Rostedt <srostedt@redhat.com>
  6. :License: The GNU Free Documentation License, Version 1.2
  7. (dual licensed under the GPL v2)
  8. :Original Reviewers: Elias Oltmanns, Randy Dunlap, Andrew Morton,
  9. John Kacur, and David Teigland.
  10. - Written for: 2.6.28-rc2
  11. - Updated for: 3.10
  12. - Updated for: 4.13 - Copyright 2017 VMware Inc. Steven Rostedt
  13. - Converted to rst format - Changbin Du <changbin.du@intel.com>
  14. Introduction
  15. ------------
  16. Ftrace is an internal tracer designed to help out developers and
  17. designers of systems to find what is going on inside the kernel.
  18. It can be used for debugging or analyzing latencies and
  19. performance issues that take place outside of user-space.
  20. Although ftrace is typically considered the function tracer, it
  21. is really a framework of several assorted tracing utilities.
  22. There's latency tracing to examine what occurs between interrupts
  23. disabled and enabled, as well as for preemption and from a time
  24. a task is woken to the task is actually scheduled in.
  25. One of the most common uses of ftrace is the event tracing.
  26. Throughout the kernel is hundreds of static event points that
  27. can be enabled via the tracefs file system to see what is
  28. going on in certain parts of the kernel.
  29. See events.rst for more information.
  30. Implementation Details
  31. ----------------------
  32. See :doc:`ftrace-design` for details for arch porters and such.
  33. The File System
  34. ---------------
  35. Ftrace uses the tracefs file system to hold the control files as
  36. well as the files to display output.
  37. When tracefs is configured into the kernel (which selecting any ftrace
  38. option will do) the directory /sys/kernel/tracing will be created. To mount
  39. this directory, you can add to your /etc/fstab file::
  40. tracefs /sys/kernel/tracing tracefs defaults 0 0
  41. Or you can mount it at run time with::
  42. mount -t tracefs nodev /sys/kernel/tracing
  43. For quicker access to that directory you may want to make a soft link to
  44. it::
  45. ln -s /sys/kernel/tracing /tracing
  46. .. attention::
  47. Before 4.1, all ftrace tracing control files were within the debugfs
  48. file system, which is typically located at /sys/kernel/debug/tracing.
  49. For backward compatibility, when mounting the debugfs file system,
  50. the tracefs file system will be automatically mounted at:
  51. /sys/kernel/debug/tracing
  52. All files located in the tracefs file system will be located in that
  53. debugfs file system directory as well.
  54. In order to not automount tracefs in the debugfs filesystem, enable the
  55. defconfig option CONFIG_TRACEFS_DISABLE_AUTOMOUNT.
  56. .. attention::
  57. Any selected ftrace option will also create the tracefs file system.
  58. The rest of the document will assume that you are in the ftrace directory
  59. (cd /sys/kernel/tracing) and will only concentrate on the files within that
  60. directory and not distract from the content with the extended
  61. "/sys/kernel/tracing" path name.
  62. That's it! (assuming that you have ftrace configured into your kernel)
  63. After mounting tracefs you will have access to the control and output files
  64. of ftrace. Here is a list of some of the key files:
  65. Note: all time values are in microseconds.
  66. current_tracer:
  67. This is used to set or display the current tracer
  68. that is configured. Changing the current tracer clears
  69. the ring buffer content as well as the "snapshot" buffer.
  70. available_tracers:
  71. This holds the different types of tracers that
  72. have been compiled into the kernel. The
  73. tracers listed here can be configured by
  74. echoing their name into current_tracer.
  75. tracing_on:
  76. This sets or displays whether writing to the trace
  77. ring buffer is enabled. Echo 0 into this file to disable
  78. the tracer or 1 to enable it. Note, this only disables
  79. writing to the ring buffer, the tracing overhead may
  80. still be occurring.
  81. The kernel function tracing_off() can be used within the
  82. kernel to disable writing to the ring buffer, which will
  83. set this file to "0". User space can re-enable tracing by
  84. echoing "1" into the file.
  85. Note, the function and event trigger "traceoff" will also
  86. set this file to zero and stop tracing. Which can also
  87. be re-enabled by user space using this file.
  88. trace:
  89. This file holds the output of the trace in a human
  90. readable format (described below). Opening this file for
  91. writing with the O_TRUNC flag clears the ring buffer content.
  92. Note, this file is not a consumer. If tracing is off
  93. (no tracer running, or tracing_on is zero), it will produce
  94. the same output each time it is read. When tracing is on,
  95. it may produce inconsistent results as it tries to read
  96. the entire buffer without consuming it.
  97. trace_pipe:
  98. The output is the same as the "trace" file but this
  99. file is meant to be streamed with live tracing.
  100. Reads from this file will block until new data is
  101. retrieved. Unlike the "trace" file, this file is a
  102. consumer. This means reading from this file causes
  103. sequential reads to display more current data. Once
  104. data is read from this file, it is consumed, and
  105. will not be read again with a sequential read. The
  106. "trace" file is static, and if the tracer is not
  107. adding more data, it will display the same
  108. information every time it is read.
  109. trace_options:
  110. This file lets the user control the amount of data
  111. that is displayed in one of the above output
  112. files. Options also exist to modify how a tracer
  113. or events work (stack traces, timestamps, etc).
  114. options:
  115. This is a directory that has a file for every available
  116. trace option (also in trace_options). Options may also be set
  117. or cleared by writing a "1" or "0" respectively into the
  118. corresponding file with the option name.
  119. tracing_max_latency:
  120. Some of the tracers record the max latency.
  121. For example, the maximum time that interrupts are disabled.
  122. The maximum time is saved in this file. The max trace will also be
  123. stored, and displayed by "trace". A new max trace will only be
  124. recorded if the latency is greater than the value in this file
  125. (in microseconds).
  126. By echoing in a time into this file, no latency will be recorded
  127. unless it is greater than the time in this file.
  128. tracing_thresh:
  129. Some latency tracers will record a trace whenever the
  130. latency is greater than the number in this file.
  131. Only active when the file contains a number greater than 0.
  132. (in microseconds)
  133. buffer_size_kb:
  134. This sets or displays the number of kilobytes each CPU
  135. buffer holds. By default, the trace buffers are the same size
  136. for each CPU. The displayed number is the size of the
  137. CPU buffer and not total size of all buffers. The
  138. trace buffers are allocated in pages (blocks of memory
  139. that the kernel uses for allocation, usually 4 KB in size).
  140. A few extra pages may be allocated to accommodate buffer management
  141. meta-data. If the last page allocated has room for more bytes
  142. than requested, the rest of the page will be used,
  143. making the actual allocation bigger than requested or shown.
  144. ( Note, the size may not be a multiple of the page size
  145. due to buffer management meta-data. )
  146. Buffer sizes for individual CPUs may vary
  147. (see "per_cpu/cpu0/buffer_size_kb" below), and if they do
  148. this file will show "X".
  149. buffer_total_size_kb:
  150. This displays the total combined size of all the trace buffers.
  151. free_buffer:
  152. If a process is performing tracing, and the ring buffer should be
  153. shrunk "freed" when the process is finished, even if it were to be
  154. killed by a signal, this file can be used for that purpose. On close
  155. of this file, the ring buffer will be resized to its minimum size.
  156. Having a process that is tracing also open this file, when the process
  157. exits its file descriptor for this file will be closed, and in doing so,
  158. the ring buffer will be "freed".
  159. It may also stop tracing if disable_on_free option is set.
  160. tracing_cpumask:
  161. This is a mask that lets the user only trace on specified CPUs.
  162. The format is a hex string representing the CPUs.
  163. set_ftrace_filter:
  164. When dynamic ftrace is configured in (see the
  165. section below "dynamic ftrace"), the code is dynamically
  166. modified (code text rewrite) to disable calling of the
  167. function profiler (mcount). This lets tracing be configured
  168. in with practically no overhead in performance. This also
  169. has a side effect of enabling or disabling specific functions
  170. to be traced. Echoing names of functions into this file
  171. will limit the trace to only those functions.
  172. This influences the tracers "function" and "function_graph"
  173. and thus also function profiling (see "function_profile_enabled").
  174. The functions listed in "available_filter_functions" are what
  175. can be written into this file.
  176. This interface also allows for commands to be used. See the
  177. "Filter commands" section for more details.
  178. As a speed up, since processing strings can be quite expensive
  179. and requires a check of all functions registered to tracing, instead
  180. an index can be written into this file. A number (starting with "1")
  181. written will instead select the same corresponding at the line position
  182. of the "available_filter_functions" file.
  183. set_ftrace_notrace:
  184. This has an effect opposite to that of
  185. set_ftrace_filter. Any function that is added here will not
  186. be traced. If a function exists in both set_ftrace_filter
  187. and set_ftrace_notrace, the function will _not_ be traced.
  188. set_ftrace_pid:
  189. Have the function tracer only trace the threads whose PID are
  190. listed in this file.
  191. If the "function-fork" option is set, then when a task whose
  192. PID is listed in this file forks, the child's PID will
  193. automatically be added to this file, and the child will be
  194. traced by the function tracer as well. This option will also
  195. cause PIDs of tasks that exit to be removed from the file.
  196. set_ftrace_notrace_pid:
  197. Have the function tracer ignore threads whose PID are listed in
  198. this file.
  199. If the "function-fork" option is set, then when a task whose
  200. PID is listed in this file forks, the child's PID will
  201. automatically be added to this file, and the child will not be
  202. traced by the function tracer as well. This option will also
  203. cause PIDs of tasks that exit to be removed from the file.
  204. If a PID is in both this file and "set_ftrace_pid", then this
  205. file takes precedence, and the thread will not be traced.
  206. set_event_pid:
  207. Have the events only trace a task with a PID listed in this file.
  208. Note, sched_switch and sched_wake_up will also trace events
  209. listed in this file.
  210. To have the PIDs of children of tasks with their PID in this file
  211. added on fork, enable the "event-fork" option. That option will also
  212. cause the PIDs of tasks to be removed from this file when the task
  213. exits.
  214. set_event_notrace_pid:
  215. Have the events not trace a task with a PID listed in this file.
  216. Note, sched_switch and sched_wakeup will trace threads not listed
  217. in this file, even if a thread's PID is in the file if the
  218. sched_switch or sched_wakeup events also trace a thread that should
  219. be traced.
  220. To have the PIDs of children of tasks with their PID in this file
  221. added on fork, enable the "event-fork" option. That option will also
  222. cause the PIDs of tasks to be removed from this file when the task
  223. exits.
  224. set_graph_function:
  225. Functions listed in this file will cause the function graph
  226. tracer to only trace these functions and the functions that
  227. they call. (See the section "dynamic ftrace" for more details).
  228. Note, set_ftrace_filter and set_ftrace_notrace still affects
  229. what functions are being traced.
  230. set_graph_notrace:
  231. Similar to set_graph_function, but will disable function graph
  232. tracing when the function is hit until it exits the function.
  233. This makes it possible to ignore tracing functions that are called
  234. by a specific function.
  235. available_filter_functions:
  236. This lists the functions that ftrace has processed and can trace.
  237. These are the function names that you can pass to
  238. "set_ftrace_filter", "set_ftrace_notrace",
  239. "set_graph_function", or "set_graph_notrace".
  240. (See the section "dynamic ftrace" below for more details.)
  241. dyn_ftrace_total_info:
  242. This file is for debugging purposes. The number of functions that
  243. have been converted to nops and are available to be traced.
  244. enabled_functions:
  245. This file is more for debugging ftrace, but can also be useful
  246. in seeing if any function has a callback attached to it.
  247. Not only does the trace infrastructure use ftrace function
  248. trace utility, but other subsystems might too. This file
  249. displays all functions that have a callback attached to them
  250. as well as the number of callbacks that have been attached.
  251. Note, a callback may also call multiple functions which will
  252. not be listed in this count.
  253. If the callback registered to be traced by a function with
  254. the "save regs" attribute (thus even more overhead), a 'R'
  255. will be displayed on the same line as the function that
  256. is returning registers.
  257. If the callback registered to be traced by a function with
  258. the "ip modify" attribute (thus the regs->ip can be changed),
  259. an 'I' will be displayed on the same line as the function that
  260. can be overridden.
  261. If the architecture supports it, it will also show what callback
  262. is being directly called by the function. If the count is greater
  263. than 1 it most likely will be ftrace_ops_list_func().
  264. If the callback of the function jumps to a trampoline that is
  265. specific to a the callback and not the standard trampoline,
  266. its address will be printed as well as the function that the
  267. trampoline calls.
  268. function_profile_enabled:
  269. When set it will enable all functions with either the function
  270. tracer, or if configured, the function graph tracer. It will
  271. keep a histogram of the number of functions that were called
  272. and if the function graph tracer was configured, it will also keep
  273. track of the time spent in those functions. The histogram
  274. content can be displayed in the files:
  275. trace_stat/function<cpu> ( function0, function1, etc).
  276. trace_stat:
  277. A directory that holds different tracing stats.
  278. kprobe_events:
  279. Enable dynamic trace points. See kprobetrace.rst.
  280. kprobe_profile:
  281. Dynamic trace points stats. See kprobetrace.rst.
  282. max_graph_depth:
  283. Used with the function graph tracer. This is the max depth
  284. it will trace into a function. Setting this to a value of
  285. one will show only the first kernel function that is called
  286. from user space.
  287. printk_formats:
  288. This is for tools that read the raw format files. If an event in
  289. the ring buffer references a string, only a pointer to the string
  290. is recorded into the buffer and not the string itself. This prevents
  291. tools from knowing what that string was. This file displays the string
  292. and address for the string allowing tools to map the pointers to what
  293. the strings were.
  294. saved_cmdlines:
  295. Only the pid of the task is recorded in a trace event unless
  296. the event specifically saves the task comm as well. Ftrace
  297. makes a cache of pid mappings to comms to try to display
  298. comms for events. If a pid for a comm is not listed, then
  299. "<...>" is displayed in the output.
  300. If the option "record-cmd" is set to "0", then comms of tasks
  301. will not be saved during recording. By default, it is enabled.
  302. saved_cmdlines_size:
  303. By default, 128 comms are saved (see "saved_cmdlines" above). To
  304. increase or decrease the amount of comms that are cached, echo
  305. the number of comms to cache into this file.
  306. saved_tgids:
  307. If the option "record-tgid" is set, on each scheduling context switch
  308. the Task Group ID of a task is saved in a table mapping the PID of
  309. the thread to its TGID. By default, the "record-tgid" option is
  310. disabled.
  311. snapshot:
  312. This displays the "snapshot" buffer and also lets the user
  313. take a snapshot of the current running trace.
  314. See the "Snapshot" section below for more details.
  315. stack_max_size:
  316. When the stack tracer is activated, this will display the
  317. maximum stack size it has encountered.
  318. See the "Stack Trace" section below.
  319. stack_trace:
  320. This displays the stack back trace of the largest stack
  321. that was encountered when the stack tracer is activated.
  322. See the "Stack Trace" section below.
  323. stack_trace_filter:
  324. This is similar to "set_ftrace_filter" but it limits what
  325. functions the stack tracer will check.
  326. trace_clock:
  327. Whenever an event is recorded into the ring buffer, a
  328. "timestamp" is added. This stamp comes from a specified
  329. clock. By default, ftrace uses the "local" clock. This
  330. clock is very fast and strictly per cpu, but on some
  331. systems it may not be monotonic with respect to other
  332. CPUs. In other words, the local clocks may not be in sync
  333. with local clocks on other CPUs.
  334. Usual clocks for tracing::
  335. # cat trace_clock
  336. [local] global counter x86-tsc
  337. The clock with the square brackets around it is the one in effect.
  338. local:
  339. Default clock, but may not be in sync across CPUs
  340. global:
  341. This clock is in sync with all CPUs but may
  342. be a bit slower than the local clock.
  343. counter:
  344. This is not a clock at all, but literally an atomic
  345. counter. It counts up one by one, but is in sync
  346. with all CPUs. This is useful when you need to
  347. know exactly the order events occurred with respect to
  348. each other on different CPUs.
  349. uptime:
  350. This uses the jiffies counter and the time stamp
  351. is relative to the time since boot up.
  352. perf:
  353. This makes ftrace use the same clock that perf uses.
  354. Eventually perf will be able to read ftrace buffers
  355. and this will help out in interleaving the data.
  356. x86-tsc:
  357. Architectures may define their own clocks. For
  358. example, x86 uses its own TSC cycle clock here.
  359. ppc-tb:
  360. This uses the powerpc timebase register value.
  361. This is in sync across CPUs and can also be used
  362. to correlate events across hypervisor/guest if
  363. tb_offset is known.
  364. mono:
  365. This uses the fast monotonic clock (CLOCK_MONOTONIC)
  366. which is monotonic and is subject to NTP rate adjustments.
  367. mono_raw:
  368. This is the raw monotonic clock (CLOCK_MONOTONIC_RAW)
  369. which is monotonic but is not subject to any rate adjustments
  370. and ticks at the same rate as the hardware clocksource.
  371. boot:
  372. This is the boot clock (CLOCK_BOOTTIME) and is based on the
  373. fast monotonic clock, but also accounts for time spent in
  374. suspend. Since the clock access is designed for use in
  375. tracing in the suspend path, some side effects are possible
  376. if clock is accessed after the suspend time is accounted before
  377. the fast mono clock is updated. In this case, the clock update
  378. appears to happen slightly sooner than it normally would have.
  379. Also on 32-bit systems, it's possible that the 64-bit boot offset
  380. sees a partial update. These effects are rare and post
  381. processing should be able to handle them. See comments in the
  382. ktime_get_boot_fast_ns() function for more information.
  383. To set a clock, simply echo the clock name into this file::
  384. # echo global > trace_clock
  385. Setting a clock clears the ring buffer content as well as the
  386. "snapshot" buffer.
  387. trace_marker:
  388. This is a very useful file for synchronizing user space
  389. with events happening in the kernel. Writing strings into
  390. this file will be written into the ftrace buffer.
  391. It is useful in applications to open this file at the start
  392. of the application and just reference the file descriptor
  393. for the file::
  394. void trace_write(const char *fmt, ...)
  395. {
  396. va_list ap;
  397. char buf[256];
  398. int n;
  399. if (trace_fd < 0)
  400. return;
  401. va_start(ap, fmt);
  402. n = vsnprintf(buf, 256, fmt, ap);
  403. va_end(ap);
  404. write(trace_fd, buf, n);
  405. }
  406. start::
  407. trace_fd = open("trace_marker", WR_ONLY);
  408. Note: Writing into the trace_marker file can also initiate triggers
  409. that are written into /sys/kernel/tracing/events/ftrace/print/trigger
  410. See "Event triggers" in Documentation/trace/events.rst and an
  411. example in Documentation/trace/histogram.rst (Section 3.)
  412. trace_marker_raw:
  413. This is similar to trace_marker above, but is meant for binary data
  414. to be written to it, where a tool can be used to parse the data
  415. from trace_pipe_raw.
  416. uprobe_events:
  417. Add dynamic tracepoints in programs.
  418. See uprobetracer.rst
  419. uprobe_profile:
  420. Uprobe statistics. See uprobetrace.txt
  421. instances:
  422. This is a way to make multiple trace buffers where different
  423. events can be recorded in different buffers.
  424. See "Instances" section below.
  425. events:
  426. This is the trace event directory. It holds event tracepoints
  427. (also known as static tracepoints) that have been compiled
  428. into the kernel. It shows what event tracepoints exist
  429. and how they are grouped by system. There are "enable"
  430. files at various levels that can enable the tracepoints
  431. when a "1" is written to them.
  432. See events.rst for more information.
  433. set_event:
  434. By echoing in the event into this file, will enable that event.
  435. See events.rst for more information.
  436. available_events:
  437. A list of events that can be enabled in tracing.
  438. See events.rst for more information.
  439. timestamp_mode:
  440. Certain tracers may change the timestamp mode used when
  441. logging trace events into the event buffer. Events with
  442. different modes can coexist within a buffer but the mode in
  443. effect when an event is logged determines which timestamp mode
  444. is used for that event. The default timestamp mode is
  445. 'delta'.
  446. Usual timestamp modes for tracing:
  447. # cat timestamp_mode
  448. [delta] absolute
  449. The timestamp mode with the square brackets around it is the
  450. one in effect.
  451. delta: Default timestamp mode - timestamp is a delta against
  452. a per-buffer timestamp.
  453. absolute: The timestamp is a full timestamp, not a delta
  454. against some other value. As such it takes up more
  455. space and is less efficient.
  456. hwlat_detector:
  457. Directory for the Hardware Latency Detector.
  458. See "Hardware Latency Detector" section below.
  459. per_cpu:
  460. This is a directory that contains the trace per_cpu information.
  461. per_cpu/cpu0/buffer_size_kb:
  462. The ftrace buffer is defined per_cpu. That is, there's a separate
  463. buffer for each CPU to allow writes to be done atomically,
  464. and free from cache bouncing. These buffers may have different
  465. size buffers. This file is similar to the buffer_size_kb
  466. file, but it only displays or sets the buffer size for the
  467. specific CPU. (here cpu0).
  468. per_cpu/cpu0/trace:
  469. This is similar to the "trace" file, but it will only display
  470. the data specific for the CPU. If written to, it only clears
  471. the specific CPU buffer.
  472. per_cpu/cpu0/trace_pipe
  473. This is similar to the "trace_pipe" file, and is a consuming
  474. read, but it will only display (and consume) the data specific
  475. for the CPU.
  476. per_cpu/cpu0/trace_pipe_raw
  477. For tools that can parse the ftrace ring buffer binary format,
  478. the trace_pipe_raw file can be used to extract the data
  479. from the ring buffer directly. With the use of the splice()
  480. system call, the buffer data can be quickly transferred to
  481. a file or to the network where a server is collecting the
  482. data.
  483. Like trace_pipe, this is a consuming reader, where multiple
  484. reads will always produce different data.
  485. per_cpu/cpu0/snapshot:
  486. This is similar to the main "snapshot" file, but will only
  487. snapshot the current CPU (if supported). It only displays
  488. the content of the snapshot for a given CPU, and if
  489. written to, only clears this CPU buffer.
  490. per_cpu/cpu0/snapshot_raw:
  491. Similar to the trace_pipe_raw, but will read the binary format
  492. from the snapshot buffer for the given CPU.
  493. per_cpu/cpu0/stats:
  494. This displays certain stats about the ring buffer:
  495. entries:
  496. The number of events that are still in the buffer.
  497. overrun:
  498. The number of lost events due to overwriting when
  499. the buffer was full.
  500. commit overrun:
  501. Should always be zero.
  502. This gets set if so many events happened within a nested
  503. event (ring buffer is re-entrant), that it fills the
  504. buffer and starts dropping events.
  505. bytes:
  506. Bytes actually read (not overwritten).
  507. oldest event ts:
  508. The oldest timestamp in the buffer
  509. now ts:
  510. The current timestamp
  511. dropped events:
  512. Events lost due to overwrite option being off.
  513. read events:
  514. The number of events read.
  515. The Tracers
  516. -----------
  517. Here is the list of current tracers that may be configured.
  518. "function"
  519. Function call tracer to trace all kernel functions.
  520. "function_graph"
  521. Similar to the function tracer except that the
  522. function tracer probes the functions on their entry
  523. whereas the function graph tracer traces on both entry
  524. and exit of the functions. It then provides the ability
  525. to draw a graph of function calls similar to C code
  526. source.
  527. "blk"
  528. The block tracer. The tracer used by the blktrace user
  529. application.
  530. "hwlat"
  531. The Hardware Latency tracer is used to detect if the hardware
  532. produces any latency. See "Hardware Latency Detector" section
  533. below.
  534. "irqsoff"
  535. Traces the areas that disable interrupts and saves
  536. the trace with the longest max latency.
  537. See tracing_max_latency. When a new max is recorded,
  538. it replaces the old trace. It is best to view this
  539. trace with the latency-format option enabled, which
  540. happens automatically when the tracer is selected.
  541. "preemptoff"
  542. Similar to irqsoff but traces and records the amount of
  543. time for which preemption is disabled.
  544. "preemptirqsoff"
  545. Similar to irqsoff and preemptoff, but traces and
  546. records the largest time for which irqs and/or preemption
  547. is disabled.
  548. "wakeup"
  549. Traces and records the max latency that it takes for
  550. the highest priority task to get scheduled after
  551. it has been woken up.
  552. Traces all tasks as an average developer would expect.
  553. "wakeup_rt"
  554. Traces and records the max latency that it takes for just
  555. RT tasks (as the current "wakeup" does). This is useful
  556. for those interested in wake up timings of RT tasks.
  557. "wakeup_dl"
  558. Traces and records the max latency that it takes for
  559. a SCHED_DEADLINE task to be woken (as the "wakeup" and
  560. "wakeup_rt" does).
  561. "mmiotrace"
  562. A special tracer that is used to trace binary module.
  563. It will trace all the calls that a module makes to the
  564. hardware. Everything it writes and reads from the I/O
  565. as well.
  566. "branch"
  567. This tracer can be configured when tracing likely/unlikely
  568. calls within the kernel. It will trace when a likely and
  569. unlikely branch is hit and if it was correct in its prediction
  570. of being correct.
  571. "nop"
  572. This is the "trace nothing" tracer. To remove all
  573. tracers from tracing simply echo "nop" into
  574. current_tracer.
  575. Error conditions
  576. ----------------
  577. For most ftrace commands, failure modes are obvious and communicated
  578. using standard return codes.
  579. For other more involved commands, extended error information may be
  580. available via the tracing/error_log file. For the commands that
  581. support it, reading the tracing/error_log file after an error will
  582. display more detailed information about what went wrong, if
  583. information is available. The tracing/error_log file is a circular
  584. error log displaying a small number (currently, 8) of ftrace errors
  585. for the last (8) failed commands.
  586. The extended error information and usage takes the form shown in
  587. this example::
  588. # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  589. echo: write error: Invalid argument
  590. # cat /sys/kernel/debug/tracing/error_log
  591. [ 5348.887237] location: error: Couldn't yyy: zzz
  592. Command: xxx
  593. ^
  594. [ 7517.023364] location: error: Bad rrr: sss
  595. Command: ppp qqq
  596. ^
  597. To clear the error log, echo the empty string into it::
  598. # echo > /sys/kernel/debug/tracing/error_log
  599. Examples of using the tracer
  600. ----------------------------
  601. Here are typical examples of using the tracers when controlling
  602. them only with the tracefs interface (without using any
  603. user-land utilities).
  604. Output format:
  605. --------------
  606. Here is an example of the output format of the file "trace"::
  607. # tracer: function
  608. #
  609. # entries-in-buffer/entries-written: 140080/250280 #P:4
  610. #
  611. # _-----=> irqs-off
  612. # / _----=> need-resched
  613. # | / _---=> hardirq/softirq
  614. # || / _--=> preempt-depth
  615. # ||| / delay
  616. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  617. # | | | |||| | |
  618. bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
  619. bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
  620. bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
  621. sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
  622. bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
  623. bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
  624. bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
  625. bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
  626. bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
  627. sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
  628. ....
  629. A header is printed with the tracer name that is represented by
  630. the trace. In this case the tracer is "function". Then it shows the
  631. number of events in the buffer as well as the total number of entries
  632. that were written. The difference is the number of entries that were
  633. lost due to the buffer filling up (250280 - 140080 = 110200 events
  634. lost).
  635. The header explains the content of the events. Task name "bash", the task
  636. PID "1977", the CPU that it was running on "000", the latency format
  637. (explained below), the timestamp in <secs>.<usecs> format, the
  638. function name that was traced "sys_close" and the parent function that
  639. called this function "system_call_fastpath". The timestamp is the time
  640. at which the function was entered.
  641. Latency trace format
  642. --------------------
  643. When the latency-format option is enabled or when one of the latency
  644. tracers is set, the trace file gives somewhat more information to see
  645. why a latency happened. Here is a typical trace::
  646. # tracer: irqsoff
  647. #
  648. # irqsoff latency trace v1.1.5 on 3.8.0-test+
  649. # --------------------------------------------------------------------
  650. # latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  651. # -----------------
  652. # | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
  653. # -----------------
  654. # => started at: __lock_task_sighand
  655. # => ended at: _raw_spin_unlock_irqrestore
  656. #
  657. #
  658. # _------=> CPU#
  659. # / _-----=> irqs-off
  660. # | / _----=> need-resched
  661. # || / _---=> hardirq/softirq
  662. # ||| / _--=> preempt-depth
  663. # |||| / delay
  664. # cmd pid ||||| time | caller
  665. # \ / ||||| \ | /
  666. ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
  667. ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
  668. ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
  669. ps-6143 2d..1 306us : <stack trace>
  670. => trace_hardirqs_on_caller
  671. => trace_hardirqs_on
  672. => _raw_spin_unlock_irqrestore
  673. => do_task_stat
  674. => proc_tgid_stat
  675. => proc_single_show
  676. => seq_read
  677. => vfs_read
  678. => sys_read
  679. => system_call_fastpath
  680. This shows that the current tracer is "irqsoff" tracing the time
  681. for which interrupts were disabled. It gives the trace version (which
  682. never changes) and the version of the kernel upon which this was executed on
  683. (3.8). Then it displays the max latency in microseconds (259 us). The number
  684. of trace entries displayed and the total number (both are four: #4/4).
  685. VP, KP, SP, and HP are always zero and are reserved for later use.
  686. #P is the number of online CPUs (#P:4).
  687. The task is the process that was running when the latency
  688. occurred. (ps pid: 6143).
  689. The start and stop (the functions in which the interrupts were
  690. disabled and enabled respectively) that caused the latencies:
  691. - __lock_task_sighand is where the interrupts were disabled.
  692. - _raw_spin_unlock_irqrestore is where they were enabled again.
  693. The next lines after the header are the trace itself. The header
  694. explains which is which.
  695. cmd: The name of the process in the trace.
  696. pid: The PID of that process.
  697. CPU#: The CPU which the process was running on.
  698. irqs-off: 'd' interrupts are disabled. '.' otherwise.
  699. .. caution:: If the architecture does not support a way to
  700. read the irq flags variable, an 'X' will always
  701. be printed here.
  702. need-resched:
  703. - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set,
  704. - 'n' only TIF_NEED_RESCHED is set,
  705. - 'p' only PREEMPT_NEED_RESCHED is set,
  706. - '.' otherwise.
  707. hardirq/softirq:
  708. - 'Z' - NMI occurred inside a hardirq
  709. - 'z' - NMI is running
  710. - 'H' - hard irq occurred inside a softirq.
  711. - 'h' - hard irq is running
  712. - 's' - soft irq is running
  713. - '.' - normal context.
  714. preempt-depth: The level of preempt_disabled
  715. The above is mostly meaningful for kernel developers.
  716. time:
  717. When the latency-format option is enabled, the trace file
  718. output includes a timestamp relative to the start of the
  719. trace. This differs from the output when latency-format
  720. is disabled, which includes an absolute timestamp.
  721. delay:
  722. This is just to help catch your eye a bit better. And
  723. needs to be fixed to be only relative to the same CPU.
  724. The marks are determined by the difference between this
  725. current trace and the next trace.
  726. - '$' - greater than 1 second
  727. - '@' - greater than 100 millisecond
  728. - '*' - greater than 10 millisecond
  729. - '#' - greater than 1000 microsecond
  730. - '!' - greater than 100 microsecond
  731. - '+' - greater than 10 microsecond
  732. - ' ' - less than or equal to 10 microsecond.
  733. The rest is the same as the 'trace' file.
  734. Note, the latency tracers will usually end with a back trace
  735. to easily find where the latency occurred.
  736. trace_options
  737. -------------
  738. The trace_options file (or the options directory) is used to control
  739. what gets printed in the trace output, or manipulate the tracers.
  740. To see what is available, simply cat the file::
  741. cat trace_options
  742. print-parent
  743. nosym-offset
  744. nosym-addr
  745. noverbose
  746. noraw
  747. nohex
  748. nobin
  749. noblock
  750. trace_printk
  751. annotate
  752. nouserstacktrace
  753. nosym-userobj
  754. noprintk-msg-only
  755. context-info
  756. nolatency-format
  757. record-cmd
  758. norecord-tgid
  759. overwrite
  760. nodisable_on_free
  761. irq-info
  762. markers
  763. noevent-fork
  764. function-trace
  765. nofunction-fork
  766. nodisplay-graph
  767. nostacktrace
  768. nobranch
  769. To disable one of the options, echo in the option prepended with
  770. "no"::
  771. echo noprint-parent > trace_options
  772. To enable an option, leave off the "no"::
  773. echo sym-offset > trace_options
  774. Here are the available options:
  775. print-parent
  776. On function traces, display the calling (parent)
  777. function as well as the function being traced.
  778. ::
  779. print-parent:
  780. bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul
  781. noprint-parent:
  782. bash-4000 [01] 1477.606694: simple_strtoul
  783. sym-offset
  784. Display not only the function name, but also the
  785. offset in the function. For example, instead of
  786. seeing just "ktime_get", you will see
  787. "ktime_get+0xb/0x20".
  788. ::
  789. sym-offset:
  790. bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0
  791. sym-addr
  792. This will also display the function address as well
  793. as the function name.
  794. ::
  795. sym-addr:
  796. bash-4000 [01] 1477.606694: simple_strtoul <c0339346>
  797. verbose
  798. This deals with the trace file when the
  799. latency-format option is enabled.
  800. ::
  801. bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \
  802. (+0.000ms): simple_strtoul (kstrtoul)
  803. raw
  804. This will display raw numbers. This option is best for
  805. use with user applications that can translate the raw
  806. numbers better than having it done in the kernel.
  807. hex
  808. Similar to raw, but the numbers will be in a hexadecimal format.
  809. bin
  810. This will print out the formats in raw binary.
  811. block
  812. When set, reading trace_pipe will not block when polled.
  813. trace_printk
  814. Can disable trace_printk() from writing into the buffer.
  815. annotate
  816. It is sometimes confusing when the CPU buffers are full
  817. and one CPU buffer had a lot of events recently, thus
  818. a shorter time frame, were another CPU may have only had
  819. a few events, which lets it have older events. When
  820. the trace is reported, it shows the oldest events first,
  821. and it may look like only one CPU ran (the one with the
  822. oldest events). When the annotate option is set, it will
  823. display when a new CPU buffer started::
  824. <idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on
  825. <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on
  826. <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore
  827. ##### CPU 2 buffer started ####
  828. <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle
  829. <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog
  830. <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock
  831. userstacktrace
  832. This option changes the trace. It records a
  833. stacktrace of the current user space thread after
  834. each trace event.
  835. sym-userobj
  836. when user stacktrace are enabled, look up which
  837. object the address belongs to, and print a
  838. relative address. This is especially useful when
  839. ASLR is on, otherwise you don't get a chance to
  840. resolve the address to object/file/line after
  841. the app is no longer running
  842. The lookup is performed when you read
  843. trace,trace_pipe. Example::
  844. a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
  845. x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
  846. printk-msg-only
  847. When set, trace_printk()s will only show the format
  848. and not their parameters (if trace_bprintk() or
  849. trace_bputs() was used to save the trace_printk()).
  850. context-info
  851. Show only the event data. Hides the comm, PID,
  852. timestamp, CPU, and other useful data.
  853. latency-format
  854. This option changes the trace output. When it is enabled,
  855. the trace displays additional information about the
  856. latency, as described in "Latency trace format".
  857. pause-on-trace
  858. When set, opening the trace file for read, will pause
  859. writing to the ring buffer (as if tracing_on was set to zero).
  860. This simulates the original behavior of the trace file.
  861. When the file is closed, tracing will be enabled again.
  862. record-cmd
  863. When any event or tracer is enabled, a hook is enabled
  864. in the sched_switch trace point to fill comm cache
  865. with mapped pids and comms. But this may cause some
  866. overhead, and if you only care about pids, and not the
  867. name of the task, disabling this option can lower the
  868. impact of tracing. See "saved_cmdlines".
  869. record-tgid
  870. When any event or tracer is enabled, a hook is enabled
  871. in the sched_switch trace point to fill the cache of
  872. mapped Thread Group IDs (TGID) mapping to pids. See
  873. "saved_tgids".
  874. overwrite
  875. This controls what happens when the trace buffer is
  876. full. If "1" (default), the oldest events are
  877. discarded and overwritten. If "0", then the newest
  878. events are discarded.
  879. (see per_cpu/cpu0/stats for overrun and dropped)
  880. disable_on_free
  881. When the free_buffer is closed, tracing will
  882. stop (tracing_on set to 0).
  883. irq-info
  884. Shows the interrupt, preempt count, need resched data.
  885. When disabled, the trace looks like::
  886. # tracer: function
  887. #
  888. # entries-in-buffer/entries-written: 144405/9452052 #P:4
  889. #
  890. # TASK-PID CPU# TIMESTAMP FUNCTION
  891. # | | | | |
  892. <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up
  893. <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89
  894. <idle>-0 [002] 23636.756055: enqueue_task <-activate_task
  895. markers
  896. When set, the trace_marker is writable (only by root).
  897. When disabled, the trace_marker will error with EINVAL
  898. on write.
  899. event-fork
  900. When set, tasks with PIDs listed in set_event_pid will have
  901. the PIDs of their children added to set_event_pid when those
  902. tasks fork. Also, when tasks with PIDs in set_event_pid exit,
  903. their PIDs will be removed from the file.
  904. This affects PIDs listed in set_event_notrace_pid as well.
  905. function-trace
  906. The latency tracers will enable function tracing
  907. if this option is enabled (default it is). When
  908. it is disabled, the latency tracers do not trace
  909. functions. This keeps the overhead of the tracer down
  910. when performing latency tests.
  911. function-fork
  912. When set, tasks with PIDs listed in set_ftrace_pid will
  913. have the PIDs of their children added to set_ftrace_pid
  914. when those tasks fork. Also, when tasks with PIDs in
  915. set_ftrace_pid exit, their PIDs will be removed from the
  916. file.
  917. This affects PIDs in set_ftrace_notrace_pid as well.
  918. display-graph
  919. When set, the latency tracers (irqsoff, wakeup, etc) will
  920. use function graph tracing instead of function tracing.
  921. stacktrace
  922. When set, a stack trace is recorded after any trace event
  923. is recorded.
  924. branch
  925. Enable branch tracing with the tracer. This enables branch
  926. tracer along with the currently set tracer. Enabling this
  927. with the "nop" tracer is the same as just enabling the
  928. "branch" tracer.
  929. .. tip:: Some tracers have their own options. They only appear in this
  930. file when the tracer is active. They always appear in the
  931. options directory.
  932. Here are the per tracer options:
  933. Options for function tracer:
  934. func_stack_trace
  935. When set, a stack trace is recorded after every
  936. function that is recorded. NOTE! Limit the functions
  937. that are recorded before enabling this, with
  938. "set_ftrace_filter" otherwise the system performance
  939. will be critically degraded. Remember to disable
  940. this option before clearing the function filter.
  941. Options for function_graph tracer:
  942. Since the function_graph tracer has a slightly different output
  943. it has its own options to control what is displayed.
  944. funcgraph-overrun
  945. When set, the "overrun" of the graph stack is
  946. displayed after each function traced. The
  947. overrun, is when the stack depth of the calls
  948. is greater than what is reserved for each task.
  949. Each task has a fixed array of functions to
  950. trace in the call graph. If the depth of the
  951. calls exceeds that, the function is not traced.
  952. The overrun is the number of functions missed
  953. due to exceeding this array.
  954. funcgraph-cpu
  955. When set, the CPU number of the CPU where the trace
  956. occurred is displayed.
  957. funcgraph-overhead
  958. When set, if the function takes longer than
  959. A certain amount, then a delay marker is
  960. displayed. See "delay" above, under the
  961. header description.
  962. funcgraph-proc
  963. Unlike other tracers, the process' command line
  964. is not displayed by default, but instead only
  965. when a task is traced in and out during a context
  966. switch. Enabling this options has the command
  967. of each process displayed at every line.
  968. funcgraph-duration
  969. At the end of each function (the return)
  970. the duration of the amount of time in the
  971. function is displayed in microseconds.
  972. funcgraph-abstime
  973. When set, the timestamp is displayed at each line.
  974. funcgraph-irqs
  975. When disabled, functions that happen inside an
  976. interrupt will not be traced.
  977. funcgraph-tail
  978. When set, the return event will include the function
  979. that it represents. By default this is off, and
  980. only a closing curly bracket "}" is displayed for
  981. the return of a function.
  982. sleep-time
  983. When running function graph tracer, to include
  984. the time a task schedules out in its function.
  985. When enabled, it will account time the task has been
  986. scheduled out as part of the function call.
  987. graph-time
  988. When running function profiler with function graph tracer,
  989. to include the time to call nested functions. When this is
  990. not set, the time reported for the function will only
  991. include the time the function itself executed for, not the
  992. time for functions that it called.
  993. Options for blk tracer:
  994. blk_classic
  995. Shows a more minimalistic output.
  996. irqsoff
  997. -------
  998. When interrupts are disabled, the CPU can not react to any other
  999. external event (besides NMIs and SMIs). This prevents the timer
  1000. interrupt from triggering or the mouse interrupt from letting
  1001. the kernel know of a new mouse event. The result is a latency
  1002. with the reaction time.
  1003. The irqsoff tracer tracks the time for which interrupts are
  1004. disabled. When a new maximum latency is hit, the tracer saves
  1005. the trace leading up to that latency point so that every time a
  1006. new maximum is reached, the old saved trace is discarded and the
  1007. new trace is saved.
  1008. To reset the maximum, echo 0 into tracing_max_latency. Here is
  1009. an example::
  1010. # echo 0 > options/function-trace
  1011. # echo irqsoff > current_tracer
  1012. # echo 1 > tracing_on
  1013. # echo 0 > tracing_max_latency
  1014. # ls -ltr
  1015. [...]
  1016. # echo 0 > tracing_on
  1017. # cat trace
  1018. # tracer: irqsoff
  1019. #
  1020. # irqsoff latency trace v1.1.5 on 3.8.0-test+
  1021. # --------------------------------------------------------------------
  1022. # latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1023. # -----------------
  1024. # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
  1025. # -----------------
  1026. # => started at: run_timer_softirq
  1027. # => ended at: run_timer_softirq
  1028. #
  1029. #
  1030. # _------=> CPU#
  1031. # / _-----=> irqs-off
  1032. # | / _----=> need-resched
  1033. # || / _---=> hardirq/softirq
  1034. # ||| / _--=> preempt-depth
  1035. # |||| / delay
  1036. # cmd pid ||||| time | caller
  1037. # \ / ||||| \ | /
  1038. <idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
  1039. <idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
  1040. <idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
  1041. <idle>-0 0dNs3 25us : <stack trace>
  1042. => _raw_spin_unlock_irq
  1043. => run_timer_softirq
  1044. => __do_softirq
  1045. => call_softirq
  1046. => do_softirq
  1047. => irq_exit
  1048. => smp_apic_timer_interrupt
  1049. => apic_timer_interrupt
  1050. => rcu_idle_exit
  1051. => cpu_idle
  1052. => rest_init
  1053. => start_kernel
  1054. => x86_64_start_reservations
  1055. => x86_64_start_kernel
  1056. Here we see that we had a latency of 16 microseconds (which is
  1057. very good). The _raw_spin_lock_irq in run_timer_softirq disabled
  1058. interrupts. The difference between the 16 and the displayed
  1059. timestamp 25us occurred because the clock was incremented
  1060. between the time of recording the max latency and the time of
  1061. recording the function that had that latency.
  1062. Note the above example had function-trace not set. If we set
  1063. function-trace, we get a much larger output::
  1064. with echo 1 > options/function-trace
  1065. # tracer: irqsoff
  1066. #
  1067. # irqsoff latency trace v1.1.5 on 3.8.0-test+
  1068. # --------------------------------------------------------------------
  1069. # latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1070. # -----------------
  1071. # | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
  1072. # -----------------
  1073. # => started at: ata_scsi_queuecmd
  1074. # => ended at: ata_scsi_queuecmd
  1075. #
  1076. #
  1077. # _------=> CPU#
  1078. # / _-----=> irqs-off
  1079. # | / _----=> need-resched
  1080. # || / _---=> hardirq/softirq
  1081. # ||| / _--=> preempt-depth
  1082. # |||| / delay
  1083. # cmd pid ||||| time | caller
  1084. # \ / ||||| \ | /
  1085. bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
  1086. bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
  1087. bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
  1088. bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
  1089. bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
  1090. bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
  1091. bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
  1092. bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
  1093. bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
  1094. [...]
  1095. bash-2042 3d..1 67us : delay_tsc <-__delay
  1096. bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
  1097. bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
  1098. bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
  1099. bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
  1100. bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
  1101. bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
  1102. bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
  1103. bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
  1104. bash-2042 3d..1 120us : <stack trace>
  1105. => _raw_spin_unlock_irqrestore
  1106. => ata_scsi_queuecmd
  1107. => scsi_dispatch_cmd
  1108. => scsi_request_fn
  1109. => __blk_run_queue_uncond
  1110. => __blk_run_queue
  1111. => blk_queue_bio
  1112. => submit_bio_noacct
  1113. => submit_bio
  1114. => submit_bh
  1115. => __ext3_get_inode_loc
  1116. => ext3_iget
  1117. => ext3_lookup
  1118. => lookup_real
  1119. => __lookup_hash
  1120. => walk_component
  1121. => lookup_last
  1122. => path_lookupat
  1123. => filename_lookup
  1124. => user_path_at_empty
  1125. => user_path_at
  1126. => vfs_fstatat
  1127. => vfs_stat
  1128. => sys_newstat
  1129. => system_call_fastpath
  1130. Here we traced a 71 microsecond latency. But we also see all the
  1131. functions that were called during that time. Note that by
  1132. enabling function tracing, we incur an added overhead. This
  1133. overhead may extend the latency times. But nevertheless, this
  1134. trace has provided some very helpful debugging information.
  1135. If we prefer function graph output instead of function, we can set
  1136. display-graph option::
  1137. with echo 1 > options/display-graph
  1138. # tracer: irqsoff
  1139. #
  1140. # irqsoff latency trace v1.1.5 on 4.20.0-rc6+
  1141. # --------------------------------------------------------------------
  1142. # latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
  1143. # -----------------
  1144. # | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
  1145. # -----------------
  1146. # => started at: free_debug_processing
  1147. # => ended at: return_to_handler
  1148. #
  1149. #
  1150. # _-----=> irqs-off
  1151. # / _----=> need-resched
  1152. # | / _---=> hardirq/softirq
  1153. # || / _--=> preempt-depth
  1154. # ||| /
  1155. # REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
  1156. # | | | | |||| | | | | | |
  1157. 0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
  1158. 0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
  1159. 1 us | 0) bash-1507 | d..2 | | set_track() {
  1160. 2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
  1161. 2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
  1162. 3 us | 0) bash-1507 | d..2 | | __unwind_start() {
  1163. 3 us | 0) bash-1507 | d..2 | | get_stack_info() {
  1164. 3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
  1165. 4 us | 0) bash-1507 | d..2 | 1.107 us | }
  1166. [...]
  1167. 3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
  1168. 3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
  1169. 3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
  1170. bash-1507 0d..1 3792us : <stack trace>
  1171. => free_debug_processing
  1172. => __slab_free
  1173. => kmem_cache_free
  1174. => vm_area_free
  1175. => remove_vma
  1176. => exit_mmap
  1177. => mmput
  1178. => begin_new_exec
  1179. => load_elf_binary
  1180. => search_binary_handler
  1181. => __do_execve_file.isra.32
  1182. => __x64_sys_execve
  1183. => do_syscall_64
  1184. => entry_SYSCALL_64_after_hwframe
  1185. preemptoff
  1186. ----------
  1187. When preemption is disabled, we may be able to receive
  1188. interrupts but the task cannot be preempted and a higher
  1189. priority task must wait for preemption to be enabled again
  1190. before it can preempt a lower priority task.
  1191. The preemptoff tracer traces the places that disable preemption.
  1192. Like the irqsoff tracer, it records the maximum latency for
  1193. which preemption was disabled. The control of preemptoff tracer
  1194. is much like the irqsoff tracer.
  1195. ::
  1196. # echo 0 > options/function-trace
  1197. # echo preemptoff > current_tracer
  1198. # echo 1 > tracing_on
  1199. # echo 0 > tracing_max_latency
  1200. # ls -ltr
  1201. [...]
  1202. # echo 0 > tracing_on
  1203. # cat trace
  1204. # tracer: preemptoff
  1205. #
  1206. # preemptoff latency trace v1.1.5 on 3.8.0-test+
  1207. # --------------------------------------------------------------------
  1208. # latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1209. # -----------------
  1210. # | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
  1211. # -----------------
  1212. # => started at: do_IRQ
  1213. # => ended at: do_IRQ
  1214. #
  1215. #
  1216. # _------=> CPU#
  1217. # / _-----=> irqs-off
  1218. # | / _----=> need-resched
  1219. # || / _---=> hardirq/softirq
  1220. # ||| / _--=> preempt-depth
  1221. # |||| / delay
  1222. # cmd pid ||||| time | caller
  1223. # \ / ||||| \ | /
  1224. sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
  1225. sshd-1991 1d..1 46us : irq_exit <-do_IRQ
  1226. sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
  1227. sshd-1991 1d..1 52us : <stack trace>
  1228. => sub_preempt_count
  1229. => irq_exit
  1230. => do_IRQ
  1231. => ret_from_intr
  1232. This has some more changes. Preemption was disabled when an
  1233. interrupt came in (notice the 'h'), and was enabled on exit.
  1234. But we also see that interrupts have been disabled when entering
  1235. the preempt off section and leaving it (the 'd'). We do not know if
  1236. interrupts were enabled in the mean time or shortly after this
  1237. was over.
  1238. ::
  1239. # tracer: preemptoff
  1240. #
  1241. # preemptoff latency trace v1.1.5 on 3.8.0-test+
  1242. # --------------------------------------------------------------------
  1243. # latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1244. # -----------------
  1245. # | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
  1246. # -----------------
  1247. # => started at: wake_up_new_task
  1248. # => ended at: task_rq_unlock
  1249. #
  1250. #
  1251. # _------=> CPU#
  1252. # / _-----=> irqs-off
  1253. # | / _----=> need-resched
  1254. # || / _---=> hardirq/softirq
  1255. # ||| / _--=> preempt-depth
  1256. # |||| / delay
  1257. # cmd pid ||||| time | caller
  1258. # \ / ||||| \ | /
  1259. bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
  1260. bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
  1261. bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
  1262. bash-1994 1d..1 1us : source_load <-select_task_rq_fair
  1263. bash-1994 1d..1 1us : source_load <-select_task_rq_fair
  1264. [...]
  1265. bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
  1266. bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
  1267. bash-1994 1d..1 13us : add_preempt_count <-irq_enter
  1268. bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
  1269. bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
  1270. bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
  1271. bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
  1272. bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
  1273. [...]
  1274. bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
  1275. bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
  1276. bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
  1277. bash-1994 1d..2 36us : do_softirq <-irq_exit
  1278. bash-1994 1d..2 36us : __do_softirq <-call_softirq
  1279. bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
  1280. bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
  1281. bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
  1282. bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
  1283. bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
  1284. [...]
  1285. bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
  1286. bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
  1287. bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
  1288. bash-1994 1dN.2 82us : idle_cpu <-irq_exit
  1289. bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
  1290. bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
  1291. bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
  1292. bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
  1293. bash-1994 1.N.1 104us : <stack trace>
  1294. => sub_preempt_count
  1295. => _raw_spin_unlock_irqrestore
  1296. => task_rq_unlock
  1297. => wake_up_new_task
  1298. => do_fork
  1299. => sys_clone
  1300. => stub_clone
  1301. The above is an example of the preemptoff trace with
  1302. function-trace set. Here we see that interrupts were not disabled
  1303. the entire time. The irq_enter code lets us know that we entered
  1304. an interrupt 'h'. Before that, the functions being traced still
  1305. show that it is not in an interrupt, but we can see from the
  1306. functions themselves that this is not the case.
  1307. preemptirqsoff
  1308. --------------
  1309. Knowing the locations that have interrupts disabled or
  1310. preemption disabled for the longest times is helpful. But
  1311. sometimes we would like to know when either preemption and/or
  1312. interrupts are disabled.
  1313. Consider the following code::
  1314. local_irq_disable();
  1315. call_function_with_irqs_off();
  1316. preempt_disable();
  1317. call_function_with_irqs_and_preemption_off();
  1318. local_irq_enable();
  1319. call_function_with_preemption_off();
  1320. preempt_enable();
  1321. The irqsoff tracer will record the total length of
  1322. call_function_with_irqs_off() and
  1323. call_function_with_irqs_and_preemption_off().
  1324. The preemptoff tracer will record the total length of
  1325. call_function_with_irqs_and_preemption_off() and
  1326. call_function_with_preemption_off().
  1327. But neither will trace the time that interrupts and/or
  1328. preemption is disabled. This total time is the time that we can
  1329. not schedule. To record this time, use the preemptirqsoff
  1330. tracer.
  1331. Again, using this trace is much like the irqsoff and preemptoff
  1332. tracers.
  1333. ::
  1334. # echo 0 > options/function-trace
  1335. # echo preemptirqsoff > current_tracer
  1336. # echo 1 > tracing_on
  1337. # echo 0 > tracing_max_latency
  1338. # ls -ltr
  1339. [...]
  1340. # echo 0 > tracing_on
  1341. # cat trace
  1342. # tracer: preemptirqsoff
  1343. #
  1344. # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
  1345. # --------------------------------------------------------------------
  1346. # latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1347. # -----------------
  1348. # | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
  1349. # -----------------
  1350. # => started at: ata_scsi_queuecmd
  1351. # => ended at: ata_scsi_queuecmd
  1352. #
  1353. #
  1354. # _------=> CPU#
  1355. # / _-----=> irqs-off
  1356. # | / _----=> need-resched
  1357. # || / _---=> hardirq/softirq
  1358. # ||| / _--=> preempt-depth
  1359. # |||| / delay
  1360. # cmd pid ||||| time | caller
  1361. # \ / ||||| \ | /
  1362. ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
  1363. ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
  1364. ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
  1365. ls-2230 3...1 111us : <stack trace>
  1366. => sub_preempt_count
  1367. => _raw_spin_unlock_irqrestore
  1368. => ata_scsi_queuecmd
  1369. => scsi_dispatch_cmd
  1370. => scsi_request_fn
  1371. => __blk_run_queue_uncond
  1372. => __blk_run_queue
  1373. => blk_queue_bio
  1374. => submit_bio_noacct
  1375. => submit_bio
  1376. => submit_bh
  1377. => ext3_bread
  1378. => ext3_dir_bread
  1379. => htree_dirblock_to_tree
  1380. => ext3_htree_fill_tree
  1381. => ext3_readdir
  1382. => vfs_readdir
  1383. => sys_getdents
  1384. => system_call_fastpath
  1385. The trace_hardirqs_off_thunk is called from assembly on x86 when
  1386. interrupts are disabled in the assembly code. Without the
  1387. function tracing, we do not know if interrupts were enabled
  1388. within the preemption points. We do see that it started with
  1389. preemption enabled.
  1390. Here is a trace with function-trace set::
  1391. # tracer: preemptirqsoff
  1392. #
  1393. # preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
  1394. # --------------------------------------------------------------------
  1395. # latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1396. # -----------------
  1397. # | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
  1398. # -----------------
  1399. # => started at: schedule
  1400. # => ended at: mutex_unlock
  1401. #
  1402. #
  1403. # _------=> CPU#
  1404. # / _-----=> irqs-off
  1405. # | / _----=> need-resched
  1406. # || / _---=> hardirq/softirq
  1407. # ||| / _--=> preempt-depth
  1408. # |||| / delay
  1409. # cmd pid ||||| time | caller
  1410. # \ / ||||| \ | /
  1411. kworker/-59 3...1 0us : __schedule <-schedule
  1412. kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
  1413. kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
  1414. kworker/-59 3d..2 1us : deactivate_task <-__schedule
  1415. kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
  1416. kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
  1417. kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
  1418. kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
  1419. kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
  1420. kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
  1421. kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
  1422. kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
  1423. kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
  1424. kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
  1425. kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
  1426. kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
  1427. kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
  1428. kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
  1429. kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
  1430. kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
  1431. kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
  1432. kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
  1433. kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
  1434. kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
  1435. kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
  1436. ls-2269 3d..2 7us : finish_task_switch <-__schedule
  1437. ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
  1438. ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
  1439. ls-2269 3d..2 8us : irq_enter <-do_IRQ
  1440. ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
  1441. ls-2269 3d..2 9us : add_preempt_count <-irq_enter
  1442. ls-2269 3d.h2 9us : exit_idle <-do_IRQ
  1443. [...]
  1444. ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
  1445. ls-2269 3d.h2 20us : irq_exit <-do_IRQ
  1446. ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
  1447. ls-2269 3d..3 21us : do_softirq <-irq_exit
  1448. ls-2269 3d..3 21us : __do_softirq <-call_softirq
  1449. ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
  1450. ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
  1451. ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
  1452. ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
  1453. ls-2269 3d.s5 31us : irq_enter <-do_IRQ
  1454. ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
  1455. [...]
  1456. ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
  1457. ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
  1458. ls-2269 3d.H5 32us : exit_idle <-do_IRQ
  1459. ls-2269 3d.H5 32us : handle_irq <-do_IRQ
  1460. ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
  1461. ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
  1462. [...]
  1463. ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
  1464. ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
  1465. ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
  1466. ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
  1467. ls-2269 3d..3 159us : idle_cpu <-irq_exit
  1468. ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
  1469. ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
  1470. ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
  1471. ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
  1472. ls-2269 3d... 186us : <stack trace>
  1473. => __mutex_unlock_slowpath
  1474. => mutex_unlock
  1475. => process_output
  1476. => n_tty_write
  1477. => tty_write
  1478. => vfs_write
  1479. => sys_write
  1480. => system_call_fastpath
  1481. This is an interesting trace. It started with kworker running and
  1482. scheduling out and ls taking over. But as soon as ls released the
  1483. rq lock and enabled interrupts (but not preemption) an interrupt
  1484. triggered. When the interrupt finished, it started running softirqs.
  1485. But while the softirq was running, another interrupt triggered.
  1486. When an interrupt is running inside a softirq, the annotation is 'H'.
  1487. wakeup
  1488. ------
  1489. One common case that people are interested in tracing is the
  1490. time it takes for a task that is woken to actually wake up.
  1491. Now for non Real-Time tasks, this can be arbitrary. But tracing
  1492. it none the less can be interesting.
  1493. Without function tracing::
  1494. # echo 0 > options/function-trace
  1495. # echo wakeup > current_tracer
  1496. # echo 1 > tracing_on
  1497. # echo 0 > tracing_max_latency
  1498. # chrt -f 5 sleep 1
  1499. # echo 0 > tracing_on
  1500. # cat trace
  1501. # tracer: wakeup
  1502. #
  1503. # wakeup latency trace v1.1.5 on 3.8.0-test+
  1504. # --------------------------------------------------------------------
  1505. # latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1506. # -----------------
  1507. # | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
  1508. # -----------------
  1509. #
  1510. # _------=> CPU#
  1511. # / _-----=> irqs-off
  1512. # | / _----=> need-resched
  1513. # || / _---=> hardirq/softirq
  1514. # ||| / _--=> preempt-depth
  1515. # |||| / delay
  1516. # cmd pid ||||| time | caller
  1517. # \ / ||||| \ | /
  1518. <idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
  1519. <idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
  1520. <idle>-0 3d..3 15us : __schedule <-schedule
  1521. <idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
  1522. The tracer only traces the highest priority task in the system
  1523. to avoid tracing the normal circumstances. Here we see that
  1524. the kworker with a nice priority of -20 (not very nice), took
  1525. just 15 microseconds from the time it woke up, to the time it
  1526. ran.
  1527. Non Real-Time tasks are not that interesting. A more interesting
  1528. trace is to concentrate only on Real-Time tasks.
  1529. wakeup_rt
  1530. ---------
  1531. In a Real-Time environment it is very important to know the
  1532. wakeup time it takes for the highest priority task that is woken
  1533. up to the time that it executes. This is also known as "schedule
  1534. latency". I stress the point that this is about RT tasks. It is
  1535. also important to know the scheduling latency of non-RT tasks,
  1536. but the average schedule latency is better for non-RT tasks.
  1537. Tools like LatencyTop are more appropriate for such
  1538. measurements.
  1539. Real-Time environments are interested in the worst case latency.
  1540. That is the longest latency it takes for something to happen,
  1541. and not the average. We can have a very fast scheduler that may
  1542. only have a large latency once in a while, but that would not
  1543. work well with Real-Time tasks. The wakeup_rt tracer was designed
  1544. to record the worst case wakeups of RT tasks. Non-RT tasks are
  1545. not recorded because the tracer only records one worst case and
  1546. tracing non-RT tasks that are unpredictable will overwrite the
  1547. worst case latency of RT tasks (just run the normal wakeup
  1548. tracer for a while to see that effect).
  1549. Since this tracer only deals with RT tasks, we will run this
  1550. slightly differently than we did with the previous tracers.
  1551. Instead of performing an 'ls', we will run 'sleep 1' under
  1552. 'chrt' which changes the priority of the task.
  1553. ::
  1554. # echo 0 > options/function-trace
  1555. # echo wakeup_rt > current_tracer
  1556. # echo 1 > tracing_on
  1557. # echo 0 > tracing_max_latency
  1558. # chrt -f 5 sleep 1
  1559. # echo 0 > tracing_on
  1560. # cat trace
  1561. # tracer: wakeup
  1562. #
  1563. # tracer: wakeup_rt
  1564. #
  1565. # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  1566. # --------------------------------------------------------------------
  1567. # latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1568. # -----------------
  1569. # | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
  1570. # -----------------
  1571. #
  1572. # _------=> CPU#
  1573. # / _-----=> irqs-off
  1574. # | / _----=> need-resched
  1575. # || / _---=> hardirq/softirq
  1576. # ||| / _--=> preempt-depth
  1577. # |||| / delay
  1578. # cmd pid ||||| time | caller
  1579. # \ / ||||| \ | /
  1580. <idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
  1581. <idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
  1582. <idle>-0 3d..3 5us : __schedule <-schedule
  1583. <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
  1584. Running this on an idle system, we see that it only took 5 microseconds
  1585. to perform the task switch. Note, since the trace point in the schedule
  1586. is before the actual "switch", we stop the tracing when the recorded task
  1587. is about to schedule in. This may change if we add a new marker at the
  1588. end of the scheduler.
  1589. Notice that the recorded task is 'sleep' with the PID of 2389
  1590. and it has an rt_prio of 5. This priority is user-space priority
  1591. and not the internal kernel priority. The policy is 1 for
  1592. SCHED_FIFO and 2 for SCHED_RR.
  1593. Note, that the trace data shows the internal priority (99 - rtprio).
  1594. ::
  1595. <idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
  1596. The 0:120:R means idle was running with a nice priority of 0 (120 - 120)
  1597. and in the running state 'R'. The sleep task was scheduled in with
  1598. 2389: 94:R. That is the priority is the kernel rtprio (99 - 5 = 94)
  1599. and it too is in the running state.
  1600. Doing the same with chrt -r 5 and function-trace set.
  1601. ::
  1602. echo 1 > options/function-trace
  1603. # tracer: wakeup_rt
  1604. #
  1605. # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  1606. # --------------------------------------------------------------------
  1607. # latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1608. # -----------------
  1609. # | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
  1610. # -----------------
  1611. #
  1612. # _------=> CPU#
  1613. # / _-----=> irqs-off
  1614. # | / _----=> need-resched
  1615. # || / _---=> hardirq/softirq
  1616. # ||| / _--=> preempt-depth
  1617. # |||| / delay
  1618. # cmd pid ||||| time | caller
  1619. # \ / ||||| \ | /
  1620. <idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
  1621. <idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
  1622. <idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
  1623. <idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
  1624. <idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
  1625. <idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
  1626. <idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
  1627. <idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
  1628. <idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
  1629. <idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
  1630. <idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
  1631. <idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
  1632. <idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
  1633. <idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
  1634. <idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
  1635. <idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
  1636. <idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
  1637. <idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
  1638. <idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
  1639. <idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
  1640. <idle>-0 3dN.2 9us : idle_cpu <-irq_exit
  1641. <idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
  1642. <idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
  1643. <idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
  1644. <idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
  1645. <idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
  1646. <idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
  1647. <idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
  1648. <idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
  1649. <idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
  1650. <idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
  1651. <idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
  1652. <idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
  1653. <idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
  1654. <idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
  1655. <idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
  1656. <idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
  1657. <idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
  1658. <idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
  1659. <idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
  1660. <idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
  1661. <idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
  1662. <idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
  1663. <idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
  1664. <idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
  1665. <idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
  1666. <idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
  1667. <idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
  1668. <idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
  1669. <idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
  1670. <idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
  1671. <idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
  1672. <idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
  1673. <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
  1674. <idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
  1675. <idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
  1676. <idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
  1677. <idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
  1678. <idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
  1679. <idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
  1680. <idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
  1681. <idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
  1682. <idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
  1683. <idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
  1684. <idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
  1685. <idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
  1686. <idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
  1687. <idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
  1688. <idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
  1689. <idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
  1690. <idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
  1691. <idle>-0 3.N.. 25us : schedule <-cpu_idle
  1692. <idle>-0 3.N.. 25us : __schedule <-preempt_schedule
  1693. <idle>-0 3.N.. 26us : add_preempt_count <-__schedule
  1694. <idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
  1695. <idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
  1696. <idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
  1697. <idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
  1698. <idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
  1699. <idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
  1700. <idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
  1701. <idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
  1702. <idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
  1703. <idle>-0 3d..3 29us : __schedule <-preempt_schedule
  1704. <idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
  1705. This isn't that big of a trace, even with function tracing enabled,
  1706. so I included the entire trace.
  1707. The interrupt went off while when the system was idle. Somewhere
  1708. before task_woken_rt() was called, the NEED_RESCHED flag was set,
  1709. this is indicated by the first occurrence of the 'N' flag.
  1710. Latency tracing and events
  1711. --------------------------
  1712. As function tracing can induce a much larger latency, but without
  1713. seeing what happens within the latency it is hard to know what
  1714. caused it. There is a middle ground, and that is with enabling
  1715. events.
  1716. ::
  1717. # echo 0 > options/function-trace
  1718. # echo wakeup_rt > current_tracer
  1719. # echo 1 > events/enable
  1720. # echo 1 > tracing_on
  1721. # echo 0 > tracing_max_latency
  1722. # chrt -f 5 sleep 1
  1723. # echo 0 > tracing_on
  1724. # cat trace
  1725. # tracer: wakeup_rt
  1726. #
  1727. # wakeup_rt latency trace v1.1.5 on 3.8.0-test+
  1728. # --------------------------------------------------------------------
  1729. # latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  1730. # -----------------
  1731. # | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
  1732. # -----------------
  1733. #
  1734. # _------=> CPU#
  1735. # / _-----=> irqs-off
  1736. # | / _----=> need-resched
  1737. # || / _---=> hardirq/softirq
  1738. # ||| / _--=> preempt-depth
  1739. # |||| / delay
  1740. # cmd pid ||||| time | caller
  1741. # \ / ||||| \ | /
  1742. <idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
  1743. <idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
  1744. <idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
  1745. <idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
  1746. <idle>-0 2.N.2 2us : power_end: cpu_id=2
  1747. <idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
  1748. <idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
  1749. <idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000
  1750. <idle>-0 2.N.2 5us : rcu_utilization: Start context switch
  1751. <idle>-0 2.N.2 5us : rcu_utilization: End context switch
  1752. <idle>-0 2d..3 6us : __schedule <-schedule
  1753. <idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
  1754. Hardware Latency Detector
  1755. -------------------------
  1756. The hardware latency detector is executed by enabling the "hwlat" tracer.
  1757. NOTE, this tracer will affect the performance of the system as it will
  1758. periodically make a CPU constantly busy with interrupts disabled.
  1759. ::
  1760. # echo hwlat > current_tracer
  1761. # sleep 100
  1762. # cat trace
  1763. # tracer: hwlat
  1764. #
  1765. # entries-in-buffer/entries-written: 13/13 #P:8
  1766. #
  1767. # _-----=> irqs-off
  1768. # / _----=> need-resched
  1769. # | / _---=> hardirq/softirq
  1770. # || / _--=> preempt-depth
  1771. # ||| / delay
  1772. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  1773. # | | | |||| | |
  1774. <...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 count:6
  1775. <...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 count:1
  1776. <...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 count:5
  1777. <...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 count:1
  1778. <...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 count:1
  1779. <...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 count:2
  1780. <...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 count:1
  1781. <...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 count:1
  1782. <...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 count:1
  1783. <...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 count:1 nmi-total:7 nmi-count:1
  1784. <...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 count:1 nmi-total:5 nmi-count:1
  1785. <...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 count:1
  1786. The above output is somewhat the same in the header. All events will have
  1787. interrupts disabled 'd'. Under the FUNCTION title there is:
  1788. #1
  1789. This is the count of events recorded that were greater than the
  1790. tracing_threshold (See below).
  1791. inner/outer(us): 11/11
  1792. This shows two numbers as "inner latency" and "outer latency". The test
  1793. runs in a loop checking a timestamp twice. The latency detected within
  1794. the two timestamps is the "inner latency" and the latency detected
  1795. after the previous timestamp and the next timestamp in the loop is
  1796. the "outer latency".
  1797. ts:1581527483.343962693
  1798. The absolute timestamp that the first latency was recorded in the window.
  1799. count:6
  1800. The number of times a latency was detected during the window.
  1801. nmi-total:7 nmi-count:1
  1802. On architectures that support it, if an NMI comes in during the
  1803. test, the time spent in NMI is reported in "nmi-total" (in
  1804. microseconds).
  1805. All architectures that have NMIs will show the "nmi-count" if an
  1806. NMI comes in during the test.
  1807. hwlat files:
  1808. tracing_threshold
  1809. This gets automatically set to "10" to represent 10
  1810. microseconds. This is the threshold of latency that
  1811. needs to be detected before the trace will be recorded.
  1812. Note, when hwlat tracer is finished (another tracer is
  1813. written into "current_tracer"), the original value for
  1814. tracing_threshold is placed back into this file.
  1815. hwlat_detector/width
  1816. The length of time the test runs with interrupts disabled.
  1817. hwlat_detector/window
  1818. The length of time of the window which the test
  1819. runs. That is, the test will run for "width"
  1820. microseconds per "window" microseconds
  1821. tracing_cpumask
  1822. When the test is started. A kernel thread is created that
  1823. runs the test. This thread will alternate between CPUs
  1824. listed in the tracing_cpumask between each period
  1825. (one "window"). To limit the test to specific CPUs
  1826. set the mask in this file to only the CPUs that the test
  1827. should run on.
  1828. function
  1829. --------
  1830. This tracer is the function tracer. Enabling the function tracer
  1831. can be done from the debug file system. Make sure the
  1832. ftrace_enabled is set; otherwise this tracer is a nop.
  1833. See the "ftrace_enabled" section below.
  1834. ::
  1835. # sysctl kernel.ftrace_enabled=1
  1836. # echo function > current_tracer
  1837. # echo 1 > tracing_on
  1838. # usleep 1
  1839. # echo 0 > tracing_on
  1840. # cat trace
  1841. # tracer: function
  1842. #
  1843. # entries-in-buffer/entries-written: 24799/24799 #P:4
  1844. #
  1845. # _-----=> irqs-off
  1846. # / _----=> need-resched
  1847. # | / _---=> hardirq/softirq
  1848. # || / _--=> preempt-depth
  1849. # ||| / delay
  1850. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  1851. # | | | |||| | |
  1852. bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
  1853. bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
  1854. bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
  1855. bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
  1856. bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
  1857. bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
  1858. bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
  1859. bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
  1860. [...]
  1861. Note: function tracer uses ring buffers to store the above
  1862. entries. The newest data may overwrite the oldest data.
  1863. Sometimes using echo to stop the trace is not sufficient because
  1864. the tracing could have overwritten the data that you wanted to
  1865. record. For this reason, it is sometimes better to disable
  1866. tracing directly from a program. This allows you to stop the
  1867. tracing at the point that you hit the part that you are
  1868. interested in. To disable the tracing directly from a C program,
  1869. something like following code snippet can be used::
  1870. int trace_fd;
  1871. [...]
  1872. int main(int argc, char *argv[]) {
  1873. [...]
  1874. trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
  1875. [...]
  1876. if (condition_hit()) {
  1877. write(trace_fd, "0", 1);
  1878. }
  1879. [...]
  1880. }
  1881. Single thread tracing
  1882. ---------------------
  1883. By writing into set_ftrace_pid you can trace a
  1884. single thread. For example::
  1885. # cat set_ftrace_pid
  1886. no pid
  1887. # echo 3111 > set_ftrace_pid
  1888. # cat set_ftrace_pid
  1889. 3111
  1890. # echo function > current_tracer
  1891. # cat trace | head
  1892. # tracer: function
  1893. #
  1894. # TASK-PID CPU# TIMESTAMP FUNCTION
  1895. # | | | | |
  1896. yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
  1897. yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
  1898. yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
  1899. yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
  1900. yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
  1901. yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
  1902. # echo > set_ftrace_pid
  1903. # cat trace |head
  1904. # tracer: function
  1905. #
  1906. # TASK-PID CPU# TIMESTAMP FUNCTION
  1907. # | | | | |
  1908. ##### CPU 3 buffer started ####
  1909. yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
  1910. yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
  1911. yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
  1912. yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
  1913. yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
  1914. If you want to trace a function when executing, you could use
  1915. something like this simple program.
  1916. ::
  1917. #include <stdio.h>
  1918. #include <stdlib.h>
  1919. #include <sys/types.h>
  1920. #include <sys/stat.h>
  1921. #include <fcntl.h>
  1922. #include <unistd.h>
  1923. #include <string.h>
  1924. #define _STR(x) #x
  1925. #define STR(x) _STR(x)
  1926. #define MAX_PATH 256
  1927. const char *find_tracefs(void)
  1928. {
  1929. static char tracefs[MAX_PATH+1];
  1930. static int tracefs_found;
  1931. char type[100];
  1932. FILE *fp;
  1933. if (tracefs_found)
  1934. return tracefs;
  1935. if ((fp = fopen("/proc/mounts","r")) == NULL) {
  1936. perror("/proc/mounts");
  1937. return NULL;
  1938. }
  1939. while (fscanf(fp, "%*s %"
  1940. STR(MAX_PATH)
  1941. "s %99s %*s %*d %*d\n",
  1942. tracefs, type) == 2) {
  1943. if (strcmp(type, "tracefs") == 0)
  1944. break;
  1945. }
  1946. fclose(fp);
  1947. if (strcmp(type, "tracefs") != 0) {
  1948. fprintf(stderr, "tracefs not mounted");
  1949. return NULL;
  1950. }
  1951. strcat(tracefs, "/tracing/");
  1952. tracefs_found = 1;
  1953. return tracefs;
  1954. }
  1955. const char *tracing_file(const char *file_name)
  1956. {
  1957. static char trace_file[MAX_PATH+1];
  1958. snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name);
  1959. return trace_file;
  1960. }
  1961. int main (int argc, char **argv)
  1962. {
  1963. if (argc < 1)
  1964. exit(-1);
  1965. if (fork() > 0) {
  1966. int fd, ffd;
  1967. char line[64];
  1968. int s;
  1969. ffd = open(tracing_file("current_tracer"), O_WRONLY);
  1970. if (ffd < 0)
  1971. exit(-1);
  1972. write(ffd, "nop", 3);
  1973. fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
  1974. s = sprintf(line, "%d\n", getpid());
  1975. write(fd, line, s);
  1976. write(ffd, "function", 8);
  1977. close(fd);
  1978. close(ffd);
  1979. execvp(argv[1], argv+1);
  1980. }
  1981. return 0;
  1982. }
  1983. Or this simple script!
  1984. ::
  1985. #!/bin/bash
  1986. tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
  1987. echo nop > $tracefs/tracing/current_tracer
  1988. echo 0 > $tracefs/tracing/tracing_on
  1989. echo $$ > $tracefs/tracing/set_ftrace_pid
  1990. echo function > $tracefs/tracing/current_tracer
  1991. echo 1 > $tracefs/tracing/tracing_on
  1992. exec "$@"
  1993. function graph tracer
  1994. ---------------------------
  1995. This tracer is similar to the function tracer except that it
  1996. probes a function on its entry and its exit. This is done by
  1997. using a dynamically allocated stack of return addresses in each
  1998. task_struct. On function entry the tracer overwrites the return
  1999. address of each function traced to set a custom probe. Thus the
  2000. original return address is stored on the stack of return address
  2001. in the task_struct.
  2002. Probing on both ends of a function leads to special features
  2003. such as:
  2004. - measure of a function's time execution
  2005. - having a reliable call stack to draw function calls graph
  2006. This tracer is useful in several situations:
  2007. - you want to find the reason of a strange kernel behavior and
  2008. need to see what happens in detail on any areas (or specific
  2009. ones).
  2010. - you are experiencing weird latencies but it's difficult to
  2011. find its origin.
  2012. - you want to find quickly which path is taken by a specific
  2013. function
  2014. - you just want to peek inside a working kernel and want to see
  2015. what happens there.
  2016. ::
  2017. # tracer: function_graph
  2018. #
  2019. # CPU DURATION FUNCTION CALLS
  2020. # | | | | | | |
  2021. 0) | sys_open() {
  2022. 0) | do_sys_open() {
  2023. 0) | getname() {
  2024. 0) | kmem_cache_alloc() {
  2025. 0) 1.382 us | __might_sleep();
  2026. 0) 2.478 us | }
  2027. 0) | strncpy_from_user() {
  2028. 0) | might_fault() {
  2029. 0) 1.389 us | __might_sleep();
  2030. 0) 2.553 us | }
  2031. 0) 3.807 us | }
  2032. 0) 7.876 us | }
  2033. 0) | alloc_fd() {
  2034. 0) 0.668 us | _spin_lock();
  2035. 0) 0.570 us | expand_files();
  2036. 0) 0.586 us | _spin_unlock();
  2037. There are several columns that can be dynamically
  2038. enabled/disabled. You can use every combination of options you
  2039. want, depending on your needs.
  2040. - The cpu number on which the function executed is default
  2041. enabled. It is sometimes better to only trace one cpu (see
  2042. tracing_cpu_mask file) or you might sometimes see unordered
  2043. function calls while cpu tracing switch.
  2044. - hide: echo nofuncgraph-cpu > trace_options
  2045. - show: echo funcgraph-cpu > trace_options
  2046. - The duration (function's time of execution) is displayed on
  2047. the closing bracket line of a function or on the same line
  2048. than the current function in case of a leaf one. It is default
  2049. enabled.
  2050. - hide: echo nofuncgraph-duration > trace_options
  2051. - show: echo funcgraph-duration > trace_options
  2052. - The overhead field precedes the duration field in case of
  2053. reached duration thresholds.
  2054. - hide: echo nofuncgraph-overhead > trace_options
  2055. - show: echo funcgraph-overhead > trace_options
  2056. - depends on: funcgraph-duration
  2057. ie::
  2058. 3) # 1837.709 us | } /* __switch_to */
  2059. 3) | finish_task_switch() {
  2060. 3) 0.313 us | _raw_spin_unlock_irq();
  2061. 3) 3.177 us | }
  2062. 3) # 1889.063 us | } /* __schedule */
  2063. 3) ! 140.417 us | } /* __schedule */
  2064. 3) # 2034.948 us | } /* schedule */
  2065. 3) * 33998.59 us | } /* schedule_preempt_disabled */
  2066. [...]
  2067. 1) 0.260 us | msecs_to_jiffies();
  2068. 1) 0.313 us | __rcu_read_unlock();
  2069. 1) + 61.770 us | }
  2070. 1) + 64.479 us | }
  2071. 1) 0.313 us | rcu_bh_qs();
  2072. 1) 0.313 us | __local_bh_enable();
  2073. 1) ! 217.240 us | }
  2074. 1) 0.365 us | idle_cpu();
  2075. 1) | rcu_irq_exit() {
  2076. 1) 0.417 us | rcu_eqs_enter_common.isra.47();
  2077. 1) 3.125 us | }
  2078. 1) ! 227.812 us | }
  2079. 1) ! 457.395 us | }
  2080. 1) @ 119760.2 us | }
  2081. [...]
  2082. 2) | handle_IPI() {
  2083. 1) 6.979 us | }
  2084. 2) 0.417 us | scheduler_ipi();
  2085. 1) 9.791 us | }
  2086. 1) + 12.917 us | }
  2087. 2) 3.490 us | }
  2088. 1) + 15.729 us | }
  2089. 1) + 18.542 us | }
  2090. 2) $ 3594274 us | }
  2091. Flags::
  2092. + means that the function exceeded 10 usecs.
  2093. ! means that the function exceeded 100 usecs.
  2094. # means that the function exceeded 1000 usecs.
  2095. * means that the function exceeded 10 msecs.
  2096. @ means that the function exceeded 100 msecs.
  2097. $ means that the function exceeded 1 sec.
  2098. - The task/pid field displays the thread cmdline and pid which
  2099. executed the function. It is default disabled.
  2100. - hide: echo nofuncgraph-proc > trace_options
  2101. - show: echo funcgraph-proc > trace_options
  2102. ie::
  2103. # tracer: function_graph
  2104. #
  2105. # CPU TASK/PID DURATION FUNCTION CALLS
  2106. # | | | | | | | | |
  2107. 0) sh-4802 | | d_free() {
  2108. 0) sh-4802 | | call_rcu() {
  2109. 0) sh-4802 | | __call_rcu() {
  2110. 0) sh-4802 | 0.616 us | rcu_process_gp_end();
  2111. 0) sh-4802 | 0.586 us | check_for_new_grace_period();
  2112. 0) sh-4802 | 2.899 us | }
  2113. 0) sh-4802 | 4.040 us | }
  2114. 0) sh-4802 | 5.151 us | }
  2115. 0) sh-4802 | + 49.370 us | }
  2116. - The absolute time field is an absolute timestamp given by the
  2117. system clock since it started. A snapshot of this time is
  2118. given on each entry/exit of functions
  2119. - hide: echo nofuncgraph-abstime > trace_options
  2120. - show: echo funcgraph-abstime > trace_options
  2121. ie::
  2122. #
  2123. # TIME CPU DURATION FUNCTION CALLS
  2124. # | | | | | | | |
  2125. 360.774522 | 1) 0.541 us | }
  2126. 360.774522 | 1) 4.663 us | }
  2127. 360.774523 | 1) 0.541 us | __wake_up_bit();
  2128. 360.774524 | 1) 6.796 us | }
  2129. 360.774524 | 1) 7.952 us | }
  2130. 360.774525 | 1) 9.063 us | }
  2131. 360.774525 | 1) 0.615 us | journal_mark_dirty();
  2132. 360.774527 | 1) 0.578 us | __brelse();
  2133. 360.774528 | 1) | reiserfs_prepare_for_journal() {
  2134. 360.774528 | 1) | unlock_buffer() {
  2135. 360.774529 | 1) | wake_up_bit() {
  2136. 360.774529 | 1) | bit_waitqueue() {
  2137. 360.774530 | 1) 0.594 us | __phys_addr();
  2138. The function name is always displayed after the closing bracket
  2139. for a function if the start of that function is not in the
  2140. trace buffer.
  2141. Display of the function name after the closing bracket may be
  2142. enabled for functions whose start is in the trace buffer,
  2143. allowing easier searching with grep for function durations.
  2144. It is default disabled.
  2145. - hide: echo nofuncgraph-tail > trace_options
  2146. - show: echo funcgraph-tail > trace_options
  2147. Example with nofuncgraph-tail (default)::
  2148. 0) | putname() {
  2149. 0) | kmem_cache_free() {
  2150. 0) 0.518 us | __phys_addr();
  2151. 0) 1.757 us | }
  2152. 0) 2.861 us | }
  2153. Example with funcgraph-tail::
  2154. 0) | putname() {
  2155. 0) | kmem_cache_free() {
  2156. 0) 0.518 us | __phys_addr();
  2157. 0) 1.757 us | } /* kmem_cache_free() */
  2158. 0) 2.861 us | } /* putname() */
  2159. You can put some comments on specific functions by using
  2160. trace_printk() For example, if you want to put a comment inside
  2161. the __might_sleep() function, you just have to include
  2162. <linux/ftrace.h> and call trace_printk() inside __might_sleep()::
  2163. trace_printk("I'm a comment!\n")
  2164. will produce::
  2165. 1) | __might_sleep() {
  2166. 1) | /* I'm a comment! */
  2167. 1) 1.449 us | }
  2168. You might find other useful features for this tracer in the
  2169. following "dynamic ftrace" section such as tracing only specific
  2170. functions or tasks.
  2171. dynamic ftrace
  2172. --------------
  2173. If CONFIG_DYNAMIC_FTRACE is set, the system will run with
  2174. virtually no overhead when function tracing is disabled. The way
  2175. this works is the mcount function call (placed at the start of
  2176. every kernel function, produced by the -pg switch in gcc),
  2177. starts of pointing to a simple return. (Enabling FTRACE will
  2178. include the -pg switch in the compiling of the kernel.)
  2179. At compile time every C file object is run through the
  2180. recordmcount program (located in the scripts directory). This
  2181. program will parse the ELF headers in the C object to find all
  2182. the locations in the .text section that call mcount. Starting
  2183. with gcc version 4.6, the -mfentry has been added for x86, which
  2184. calls "__fentry__" instead of "mcount". Which is called before
  2185. the creation of the stack frame.
  2186. Note, not all sections are traced. They may be prevented by either
  2187. a notrace, or blocked another way and all inline functions are not
  2188. traced. Check the "available_filter_functions" file to see what functions
  2189. can be traced.
  2190. A section called "__mcount_loc" is created that holds
  2191. references to all the mcount/fentry call sites in the .text section.
  2192. The recordmcount program re-links this section back into the
  2193. original object. The final linking stage of the kernel will add all these
  2194. references into a single table.
  2195. On boot up, before SMP is initialized, the dynamic ftrace code
  2196. scans this table and updates all the locations into nops. It
  2197. also records the locations, which are added to the
  2198. available_filter_functions list. Modules are processed as they
  2199. are loaded and before they are executed. When a module is
  2200. unloaded, it also removes its functions from the ftrace function
  2201. list. This is automatic in the module unload code, and the
  2202. module author does not need to worry about it.
  2203. When tracing is enabled, the process of modifying the function
  2204. tracepoints is dependent on architecture. The old method is to use
  2205. kstop_machine to prevent races with the CPUs executing code being
  2206. modified (which can cause the CPU to do undesirable things, especially
  2207. if the modified code crosses cache (or page) boundaries), and the nops are
  2208. patched back to calls. But this time, they do not call mcount
  2209. (which is just a function stub). They now call into the ftrace
  2210. infrastructure.
  2211. The new method of modifying the function tracepoints is to place
  2212. a breakpoint at the location to be modified, sync all CPUs, modify
  2213. the rest of the instruction not covered by the breakpoint. Sync
  2214. all CPUs again, and then remove the breakpoint with the finished
  2215. version to the ftrace call site.
  2216. Some archs do not even need to monkey around with the synchronization,
  2217. and can just slap the new code on top of the old without any
  2218. problems with other CPUs executing it at the same time.
  2219. One special side-effect to the recording of the functions being
  2220. traced is that we can now selectively choose which functions we
  2221. wish to trace and which ones we want the mcount calls to remain
  2222. as nops.
  2223. Two files are used, one for enabling and one for disabling the
  2224. tracing of specified functions. They are:
  2225. set_ftrace_filter
  2226. and
  2227. set_ftrace_notrace
  2228. A list of available functions that you can add to these files is
  2229. listed in:
  2230. available_filter_functions
  2231. ::
  2232. # cat available_filter_functions
  2233. put_prev_task_idle
  2234. kmem_cache_create
  2235. pick_next_task_rt
  2236. get_online_cpus
  2237. pick_next_task_fair
  2238. mutex_lock
  2239. [...]
  2240. If I am only interested in sys_nanosleep and hrtimer_interrupt::
  2241. # echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
  2242. # echo function > current_tracer
  2243. # echo 1 > tracing_on
  2244. # usleep 1
  2245. # echo 0 > tracing_on
  2246. # cat trace
  2247. # tracer: function
  2248. #
  2249. # entries-in-buffer/entries-written: 5/5 #P:4
  2250. #
  2251. # _-----=> irqs-off
  2252. # / _----=> need-resched
  2253. # | / _---=> hardirq/softirq
  2254. # || / _--=> preempt-depth
  2255. # ||| / delay
  2256. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2257. # | | | |||| | |
  2258. usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
  2259. <idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
  2260. usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
  2261. <idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
  2262. <idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
  2263. To see which functions are being traced, you can cat the file:
  2264. ::
  2265. # cat set_ftrace_filter
  2266. hrtimer_interrupt
  2267. sys_nanosleep
  2268. Perhaps this is not enough. The filters also allow glob(7) matching.
  2269. ``<match>*``
  2270. will match functions that begin with <match>
  2271. ``*<match>``
  2272. will match functions that end with <match>
  2273. ``*<match>*``
  2274. will match functions that have <match> in it
  2275. ``<match1>*<match2>``
  2276. will match functions that begin with <match1> and end with <match2>
  2277. .. note::
  2278. It is better to use quotes to enclose the wild cards,
  2279. otherwise the shell may expand the parameters into names
  2280. of files in the local directory.
  2281. ::
  2282. # echo 'hrtimer_*' > set_ftrace_filter
  2283. Produces::
  2284. # tracer: function
  2285. #
  2286. # entries-in-buffer/entries-written: 897/897 #P:4
  2287. #
  2288. # _-----=> irqs-off
  2289. # / _----=> need-resched
  2290. # | / _---=> hardirq/softirq
  2291. # || / _--=> preempt-depth
  2292. # ||| / delay
  2293. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2294. # | | | |||| | |
  2295. <idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
  2296. <idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
  2297. <idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
  2298. <idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
  2299. <idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
  2300. <idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
  2301. <idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
  2302. <idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
  2303. Notice that we lost the sys_nanosleep.
  2304. ::
  2305. # cat set_ftrace_filter
  2306. hrtimer_run_queues
  2307. hrtimer_run_pending
  2308. hrtimer_init
  2309. hrtimer_cancel
  2310. hrtimer_try_to_cancel
  2311. hrtimer_forward
  2312. hrtimer_start
  2313. hrtimer_reprogram
  2314. hrtimer_force_reprogram
  2315. hrtimer_get_next_event
  2316. hrtimer_interrupt
  2317. hrtimer_nanosleep
  2318. hrtimer_wakeup
  2319. hrtimer_get_remaining
  2320. hrtimer_get_res
  2321. hrtimer_init_sleeper
  2322. This is because the '>' and '>>' act just like they do in bash.
  2323. To rewrite the filters, use '>'
  2324. To append to the filters, use '>>'
  2325. To clear out a filter so that all functions will be recorded
  2326. again::
  2327. # echo > set_ftrace_filter
  2328. # cat set_ftrace_filter
  2329. #
  2330. Again, now we want to append.
  2331. ::
  2332. # echo sys_nanosleep > set_ftrace_filter
  2333. # cat set_ftrace_filter
  2334. sys_nanosleep
  2335. # echo 'hrtimer_*' >> set_ftrace_filter
  2336. # cat set_ftrace_filter
  2337. hrtimer_run_queues
  2338. hrtimer_run_pending
  2339. hrtimer_init
  2340. hrtimer_cancel
  2341. hrtimer_try_to_cancel
  2342. hrtimer_forward
  2343. hrtimer_start
  2344. hrtimer_reprogram
  2345. hrtimer_force_reprogram
  2346. hrtimer_get_next_event
  2347. hrtimer_interrupt
  2348. sys_nanosleep
  2349. hrtimer_nanosleep
  2350. hrtimer_wakeup
  2351. hrtimer_get_remaining
  2352. hrtimer_get_res
  2353. hrtimer_init_sleeper
  2354. The set_ftrace_notrace prevents those functions from being
  2355. traced.
  2356. ::
  2357. # echo '*preempt*' '*lock*' > set_ftrace_notrace
  2358. Produces::
  2359. # tracer: function
  2360. #
  2361. # entries-in-buffer/entries-written: 39608/39608 #P:4
  2362. #
  2363. # _-----=> irqs-off
  2364. # / _----=> need-resched
  2365. # | / _---=> hardirq/softirq
  2366. # || / _--=> preempt-depth
  2367. # ||| / delay
  2368. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2369. # | | | |||| | |
  2370. bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
  2371. bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
  2372. bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
  2373. bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
  2374. bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
  2375. bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
  2376. bash-1994 [000] .... 4342.324899: do_truncate <-do_last
  2377. bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate
  2378. bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
  2379. bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
  2380. bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
  2381. bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
  2382. We can see that there's no more lock or preempt tracing.
  2383. Selecting function filters via index
  2384. ------------------------------------
  2385. Because processing of strings is expensive (the address of the function
  2386. needs to be looked up before comparing to the string being passed in),
  2387. an index can be used as well to enable functions. This is useful in the
  2388. case of setting thousands of specific functions at a time. By passing
  2389. in a list of numbers, no string processing will occur. Instead, the function
  2390. at the specific location in the internal array (which corresponds to the
  2391. functions in the "available_filter_functions" file), is selected.
  2392. ::
  2393. # echo 1 > set_ftrace_filter
  2394. Will select the first function listed in "available_filter_functions"
  2395. ::
  2396. # head -1 available_filter_functions
  2397. trace_initcall_finish_cb
  2398. # cat set_ftrace_filter
  2399. trace_initcall_finish_cb
  2400. # head -50 available_filter_functions | tail -1
  2401. x86_pmu_commit_txn
  2402. # echo 1 50 > set_ftrace_filter
  2403. # cat set_ftrace_filter
  2404. trace_initcall_finish_cb
  2405. x86_pmu_commit_txn
  2406. Dynamic ftrace with the function graph tracer
  2407. ---------------------------------------------
  2408. Although what has been explained above concerns both the
  2409. function tracer and the function-graph-tracer, there are some
  2410. special features only available in the function-graph tracer.
  2411. If you want to trace only one function and all of its children,
  2412. you just have to echo its name into set_graph_function::
  2413. echo __do_fault > set_graph_function
  2414. will produce the following "expanded" trace of the __do_fault()
  2415. function::
  2416. 0) | __do_fault() {
  2417. 0) | filemap_fault() {
  2418. 0) | find_lock_page() {
  2419. 0) 0.804 us | find_get_page();
  2420. 0) | __might_sleep() {
  2421. 0) 1.329 us | }
  2422. 0) 3.904 us | }
  2423. 0) 4.979 us | }
  2424. 0) 0.653 us | _spin_lock();
  2425. 0) 0.578 us | page_add_file_rmap();
  2426. 0) 0.525 us | native_set_pte_at();
  2427. 0) 0.585 us | _spin_unlock();
  2428. 0) | unlock_page() {
  2429. 0) 0.541 us | page_waitqueue();
  2430. 0) 0.639 us | __wake_up_bit();
  2431. 0) 2.786 us | }
  2432. 0) + 14.237 us | }
  2433. 0) | __do_fault() {
  2434. 0) | filemap_fault() {
  2435. 0) | find_lock_page() {
  2436. 0) 0.698 us | find_get_page();
  2437. 0) | __might_sleep() {
  2438. 0) 1.412 us | }
  2439. 0) 3.950 us | }
  2440. 0) 5.098 us | }
  2441. 0) 0.631 us | _spin_lock();
  2442. 0) 0.571 us | page_add_file_rmap();
  2443. 0) 0.526 us | native_set_pte_at();
  2444. 0) 0.586 us | _spin_unlock();
  2445. 0) | unlock_page() {
  2446. 0) 0.533 us | page_waitqueue();
  2447. 0) 0.638 us | __wake_up_bit();
  2448. 0) 2.793 us | }
  2449. 0) + 14.012 us | }
  2450. You can also expand several functions at once::
  2451. echo sys_open > set_graph_function
  2452. echo sys_close >> set_graph_function
  2453. Now if you want to go back to trace all functions you can clear
  2454. this special filter via::
  2455. echo > set_graph_function
  2456. ftrace_enabled
  2457. --------------
  2458. Note, the proc sysctl ftrace_enable is a big on/off switch for the
  2459. function tracer. By default it is enabled (when function tracing is
  2460. enabled in the kernel). If it is disabled, all function tracing is
  2461. disabled. This includes not only the function tracers for ftrace, but
  2462. also for any other uses (perf, kprobes, stack tracing, profiling, etc). It
  2463. cannot be disabled if there is a callback with FTRACE_OPS_FL_PERMANENT set
  2464. registered.
  2465. Please disable this with care.
  2466. This can be disable (and enabled) with::
  2467. sysctl kernel.ftrace_enabled=0
  2468. sysctl kernel.ftrace_enabled=1
  2469. or
  2470. echo 0 > /proc/sys/kernel/ftrace_enabled
  2471. echo 1 > /proc/sys/kernel/ftrace_enabled
  2472. Filter commands
  2473. ---------------
  2474. A few commands are supported by the set_ftrace_filter interface.
  2475. Trace commands have the following format::
  2476. <function>:<command>:<parameter>
  2477. The following commands are supported:
  2478. - mod:
  2479. This command enables function filtering per module. The
  2480. parameter defines the module. For example, if only the write*
  2481. functions in the ext3 module are desired, run:
  2482. echo 'write*:mod:ext3' > set_ftrace_filter
  2483. This command interacts with the filter in the same way as
  2484. filtering based on function names. Thus, adding more functions
  2485. in a different module is accomplished by appending (>>) to the
  2486. filter file. Remove specific module functions by prepending
  2487. '!'::
  2488. echo '!writeback*:mod:ext3' >> set_ftrace_filter
  2489. Mod command supports module globbing. Disable tracing for all
  2490. functions except a specific module::
  2491. echo '!*:mod:!ext3' >> set_ftrace_filter
  2492. Disable tracing for all modules, but still trace kernel::
  2493. echo '!*:mod:*' >> set_ftrace_filter
  2494. Enable filter only for kernel::
  2495. echo '*write*:mod:!*' >> set_ftrace_filter
  2496. Enable filter for module globbing::
  2497. echo '*write*:mod:*snd*' >> set_ftrace_filter
  2498. - traceon/traceoff:
  2499. These commands turn tracing on and off when the specified
  2500. functions are hit. The parameter determines how many times the
  2501. tracing system is turned on and off. If unspecified, there is
  2502. no limit. For example, to disable tracing when a schedule bug
  2503. is hit the first 5 times, run::
  2504. echo '__schedule_bug:traceoff:5' > set_ftrace_filter
  2505. To always disable tracing when __schedule_bug is hit::
  2506. echo '__schedule_bug:traceoff' > set_ftrace_filter
  2507. These commands are cumulative whether or not they are appended
  2508. to set_ftrace_filter. To remove a command, prepend it by '!'
  2509. and drop the parameter::
  2510. echo '!__schedule_bug:traceoff:0' > set_ftrace_filter
  2511. The above removes the traceoff command for __schedule_bug
  2512. that have a counter. To remove commands without counters::
  2513. echo '!__schedule_bug:traceoff' > set_ftrace_filter
  2514. - snapshot:
  2515. Will cause a snapshot to be triggered when the function is hit.
  2516. ::
  2517. echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter
  2518. To only snapshot once:
  2519. ::
  2520. echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter
  2521. To remove the above commands::
  2522. echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter
  2523. echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter
  2524. - enable_event/disable_event:
  2525. These commands can enable or disable a trace event. Note, because
  2526. function tracing callbacks are very sensitive, when these commands
  2527. are registered, the trace point is activated, but disabled in
  2528. a "soft" mode. That is, the tracepoint will be called, but
  2529. just will not be traced. The event tracepoint stays in this mode
  2530. as long as there's a command that triggers it.
  2531. ::
  2532. echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \
  2533. set_ftrace_filter
  2534. The format is::
  2535. <function>:enable_event:<system>:<event>[:count]
  2536. <function>:disable_event:<system>:<event>[:count]
  2537. To remove the events commands::
  2538. echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \
  2539. set_ftrace_filter
  2540. echo '!schedule:disable_event:sched:sched_switch' > \
  2541. set_ftrace_filter
  2542. - dump:
  2543. When the function is hit, it will dump the contents of the ftrace
  2544. ring buffer to the console. This is useful if you need to debug
  2545. something, and want to dump the trace when a certain function
  2546. is hit. Perhaps it's a function that is called before a triple
  2547. fault happens and does not allow you to get a regular dump.
  2548. - cpudump:
  2549. When the function is hit, it will dump the contents of the ftrace
  2550. ring buffer for the current CPU to the console. Unlike the "dump"
  2551. command, it only prints out the contents of the ring buffer for the
  2552. CPU that executed the function that triggered the dump.
  2553. - stacktrace:
  2554. When the function is hit, a stack trace is recorded.
  2555. trace_pipe
  2556. ----------
  2557. The trace_pipe outputs the same content as the trace file, but
  2558. the effect on the tracing is different. Every read from
  2559. trace_pipe is consumed. This means that subsequent reads will be
  2560. different. The trace is live.
  2561. ::
  2562. # echo function > current_tracer
  2563. # cat trace_pipe > /tmp/trace.out &
  2564. [1] 4153
  2565. # echo 1 > tracing_on
  2566. # usleep 1
  2567. # echo 0 > tracing_on
  2568. # cat trace
  2569. # tracer: function
  2570. #
  2571. # entries-in-buffer/entries-written: 0/0 #P:4
  2572. #
  2573. # _-----=> irqs-off
  2574. # / _----=> need-resched
  2575. # | / _---=> hardirq/softirq
  2576. # || / _--=> preempt-depth
  2577. # ||| / delay
  2578. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2579. # | | | |||| | |
  2580. #
  2581. # cat /tmp/trace.out
  2582. bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
  2583. bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
  2584. bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
  2585. bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
  2586. bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
  2587. bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
  2588. bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
  2589. bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
  2590. bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
  2591. Note, reading the trace_pipe file will block until more input is
  2592. added. This is contrary to the trace file. If any process opened
  2593. the trace file for reading, it will actually disable tracing and
  2594. prevent new entries from being added. The trace_pipe file does
  2595. not have this limitation.
  2596. trace entries
  2597. -------------
  2598. Having too much or not enough data can be troublesome in
  2599. diagnosing an issue in the kernel. The file buffer_size_kb is
  2600. used to modify the size of the internal trace buffers. The
  2601. number listed is the number of entries that can be recorded per
  2602. CPU. To know the full size, multiply the number of possible CPUs
  2603. with the number of entries.
  2604. ::
  2605. # cat buffer_size_kb
  2606. 1408 (units kilobytes)
  2607. Or simply read buffer_total_size_kb
  2608. ::
  2609. # cat buffer_total_size_kb
  2610. 5632
  2611. To modify the buffer, simple echo in a number (in 1024 byte segments).
  2612. ::
  2613. # echo 10000 > buffer_size_kb
  2614. # cat buffer_size_kb
  2615. 10000 (units kilobytes)
  2616. It will try to allocate as much as possible. If you allocate too
  2617. much, it can cause Out-Of-Memory to trigger.
  2618. ::
  2619. # echo 1000000000000 > buffer_size_kb
  2620. -bash: echo: write error: Cannot allocate memory
  2621. # cat buffer_size_kb
  2622. 85
  2623. The per_cpu buffers can be changed individually as well:
  2624. ::
  2625. # echo 10000 > per_cpu/cpu0/buffer_size_kb
  2626. # echo 100 > per_cpu/cpu1/buffer_size_kb
  2627. When the per_cpu buffers are not the same, the buffer_size_kb
  2628. at the top level will just show an X
  2629. ::
  2630. # cat buffer_size_kb
  2631. X
  2632. This is where the buffer_total_size_kb is useful:
  2633. ::
  2634. # cat buffer_total_size_kb
  2635. 12916
  2636. Writing to the top level buffer_size_kb will reset all the buffers
  2637. to be the same again.
  2638. Snapshot
  2639. --------
  2640. CONFIG_TRACER_SNAPSHOT makes a generic snapshot feature
  2641. available to all non latency tracers. (Latency tracers which
  2642. record max latency, such as "irqsoff" or "wakeup", can't use
  2643. this feature, since those are already using the snapshot
  2644. mechanism internally.)
  2645. Snapshot preserves a current trace buffer at a particular point
  2646. in time without stopping tracing. Ftrace swaps the current
  2647. buffer with a spare buffer, and tracing continues in the new
  2648. current (=previous spare) buffer.
  2649. The following tracefs files in "tracing" are related to this
  2650. feature:
  2651. snapshot:
  2652. This is used to take a snapshot and to read the output
  2653. of the snapshot. Echo 1 into this file to allocate a
  2654. spare buffer and to take a snapshot (swap), then read
  2655. the snapshot from this file in the same format as
  2656. "trace" (described above in the section "The File
  2657. System"). Both reads snapshot and tracing are executable
  2658. in parallel. When the spare buffer is allocated, echoing
  2659. 0 frees it, and echoing else (positive) values clear the
  2660. snapshot contents.
  2661. More details are shown in the table below.
  2662. +--------------+------------+------------+------------+
  2663. |status\\input | 0 | 1 | else |
  2664. +==============+============+============+============+
  2665. |not allocated |(do nothing)| alloc+swap |(do nothing)|
  2666. +--------------+------------+------------+------------+
  2667. |allocated | free | swap | clear |
  2668. +--------------+------------+------------+------------+
  2669. Here is an example of using the snapshot feature.
  2670. ::
  2671. # echo 1 > events/sched/enable
  2672. # echo 1 > snapshot
  2673. # cat snapshot
  2674. # tracer: nop
  2675. #
  2676. # entries-in-buffer/entries-written: 71/71 #P:8
  2677. #
  2678. # _-----=> irqs-off
  2679. # / _----=> need-resched
  2680. # | / _---=> hardirq/softirq
  2681. # || / _--=> preempt-depth
  2682. # ||| / delay
  2683. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2684. # | | | |||| | |
  2685. <idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120
  2686. sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120 prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120
  2687. [...]
  2688. <idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120
  2689. # cat trace
  2690. # tracer: nop
  2691. #
  2692. # entries-in-buffer/entries-written: 77/77 #P:8
  2693. #
  2694. # _-----=> irqs-off
  2695. # / _----=> need-resched
  2696. # | / _---=> hardirq/softirq
  2697. # || / _--=> preempt-depth
  2698. # ||| / delay
  2699. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2700. # | | | |||| | |
  2701. <idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
  2702. snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
  2703. [...]
  2704. If you try to use this snapshot feature when current tracer is
  2705. one of the latency tracers, you will get the following results.
  2706. ::
  2707. # echo wakeup > current_tracer
  2708. # echo 1 > snapshot
  2709. bash: echo: write error: Device or resource busy
  2710. # cat snapshot
  2711. cat: snapshot: Device or resource busy
  2712. Instances
  2713. ---------
  2714. In the tracefs tracing directory is a directory called "instances".
  2715. This directory can have new directories created inside of it using
  2716. mkdir, and removing directories with rmdir. The directory created
  2717. with mkdir in this directory will already contain files and other
  2718. directories after it is created.
  2719. ::
  2720. # mkdir instances/foo
  2721. # ls instances/foo
  2722. buffer_size_kb buffer_total_size_kb events free_buffer per_cpu
  2723. set_event snapshot trace trace_clock trace_marker trace_options
  2724. trace_pipe tracing_on
  2725. As you can see, the new directory looks similar to the tracing directory
  2726. itself. In fact, it is very similar, except that the buffer and
  2727. events are agnostic from the main directory, or from any other
  2728. instances that are created.
  2729. The files in the new directory work just like the files with the
  2730. same name in the tracing directory except the buffer that is used
  2731. is a separate and new buffer. The files affect that buffer but do not
  2732. affect the main buffer with the exception of trace_options. Currently,
  2733. the trace_options affect all instances and the top level buffer
  2734. the same, but this may change in future releases. That is, options
  2735. may become specific to the instance they reside in.
  2736. Notice that none of the function tracer files are there, nor is
  2737. current_tracer and available_tracers. This is because the buffers
  2738. can currently only have events enabled for them.
  2739. ::
  2740. # mkdir instances/foo
  2741. # mkdir instances/bar
  2742. # mkdir instances/zoot
  2743. # echo 100000 > buffer_size_kb
  2744. # echo 1000 > instances/foo/buffer_size_kb
  2745. # echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
  2746. # echo function > current_trace
  2747. # echo 1 > instances/foo/events/sched/sched_wakeup/enable
  2748. # echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
  2749. # echo 1 > instances/foo/events/sched/sched_switch/enable
  2750. # echo 1 > instances/bar/events/irq/enable
  2751. # echo 1 > instances/zoot/events/syscalls/enable
  2752. # cat trace_pipe
  2753. CPU:2 [LOST 11745 EVENTS]
  2754. bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
  2755. bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
  2756. bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
  2757. bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
  2758. bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
  2759. bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
  2760. bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
  2761. bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
  2762. bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
  2763. bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
  2764. bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
  2765. [...]
  2766. # cat instances/foo/trace_pipe
  2767. bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
  2768. bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
  2769. <idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003
  2770. <idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120
  2771. rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
  2772. bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
  2773. bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
  2774. bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120
  2775. kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001
  2776. kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120
  2777. [...]
  2778. # cat instances/bar/trace_pipe
  2779. migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
  2780. <idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
  2781. bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
  2782. bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
  2783. bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
  2784. bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
  2785. bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
  2786. bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
  2787. sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
  2788. sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
  2789. sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
  2790. sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
  2791. [...]
  2792. # cat instances/zoot/trace
  2793. # tracer: nop
  2794. #
  2795. # entries-in-buffer/entries-written: 18996/18996 #P:4
  2796. #
  2797. # _-----=> irqs-off
  2798. # / _----=> need-resched
  2799. # | / _---=> hardirq/softirq
  2800. # || / _--=> preempt-depth
  2801. # ||| / delay
  2802. # TASK-PID CPU# |||| TIMESTAMP FUNCTION
  2803. # | | | |||| | |
  2804. bash-1998 [000] d... 140.733501: sys_write -> 0x2
  2805. bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
  2806. bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
  2807. bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
  2808. bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
  2809. bash-1998 [000] d... 140.733510: sys_close(fd: a)
  2810. bash-1998 [000] d... 140.733510: sys_close -> 0x0
  2811. bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)
  2812. bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
  2813. bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)
  2814. bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
  2815. You can see that the trace of the top most trace buffer shows only
  2816. the function tracing. The foo instance displays wakeups and task
  2817. switches.
  2818. To remove the instances, simply delete their directories:
  2819. ::
  2820. # rmdir instances/foo
  2821. # rmdir instances/bar
  2822. # rmdir instances/zoot
  2823. Note, if a process has a trace file open in one of the instance
  2824. directories, the rmdir will fail with EBUSY.
  2825. Stack trace
  2826. -----------
  2827. Since the kernel has a fixed sized stack, it is important not to
  2828. waste it in functions. A kernel developer must be conscience of
  2829. what they allocate on the stack. If they add too much, the system
  2830. can be in danger of a stack overflow, and corruption will occur,
  2831. usually leading to a system panic.
  2832. There are some tools that check this, usually with interrupts
  2833. periodically checking usage. But if you can perform a check
  2834. at every function call that will become very useful. As ftrace provides
  2835. a function tracer, it makes it convenient to check the stack size
  2836. at every function call. This is enabled via the stack tracer.
  2837. CONFIG_STACK_TRACER enables the ftrace stack tracing functionality.
  2838. To enable it, write a '1' into /proc/sys/kernel/stack_tracer_enabled.
  2839. ::
  2840. # echo 1 > /proc/sys/kernel/stack_tracer_enabled
  2841. You can also enable it from the kernel command line to trace
  2842. the stack size of the kernel during boot up, by adding "stacktrace"
  2843. to the kernel command line parameter.
  2844. After running it for a few minutes, the output looks like:
  2845. ::
  2846. # cat stack_max_size
  2847. 2928
  2848. # cat stack_trace
  2849. Depth Size Location (18 entries)
  2850. ----- ---- --------
  2851. 0) 2928 224 update_sd_lb_stats+0xbc/0x4ac
  2852. 1) 2704 160 find_busiest_group+0x31/0x1f1
  2853. 2) 2544 256 load_balance+0xd9/0x662
  2854. 3) 2288 80 idle_balance+0xbb/0x130
  2855. 4) 2208 128 __schedule+0x26e/0x5b9
  2856. 5) 2080 16 schedule+0x64/0x66
  2857. 6) 2064 128 schedule_timeout+0x34/0xe0
  2858. 7) 1936 112 wait_for_common+0x97/0xf1
  2859. 8) 1824 16 wait_for_completion+0x1d/0x1f
  2860. 9) 1808 128 flush_work+0xfe/0x119
  2861. 10) 1680 16 tty_flush_to_ldisc+0x1e/0x20
  2862. 11) 1664 48 input_available_p+0x1d/0x5c
  2863. 12) 1616 48 n_tty_poll+0x6d/0x134
  2864. 13) 1568 64 tty_poll+0x64/0x7f
  2865. 14) 1504 880 do_select+0x31e/0x511
  2866. 15) 624 400 core_sys_select+0x177/0x216
  2867. 16) 224 96 sys_select+0x91/0xb9
  2868. 17) 128 128 system_call_fastpath+0x16/0x1b
  2869. Note, if -mfentry is being used by gcc, functions get traced before
  2870. they set up the stack frame. This means that leaf level functions
  2871. are not tested by the stack tracer when -mfentry is used.
  2872. Currently, -mfentry is used by gcc 4.6.0 and above on x86 only.
  2873. More
  2874. ----
  2875. More details can be found in the source code, in the `kernel/trace/*.c` files.