TRACE-CMD-REPORT(1) libtracefs Manual TRACE-CMD-REPORT(1)

trace-cmd-report - نمایش ردگیری ایجادشده توسط trace-cmd record به صورت ASCII

trace-cmd report [OPTIONS] [input-file [input-file ...]]

دستور trace-cmd(1) report گزارشی خوانا برای انسان از ردگیری (trace) ایجادشده توسط trace-cmd record در خروجی ارائه می‌دهد.

-i input-file

به‌طور پیش‌فرض، trace-cmd report فایل trace.dat را می‌خواند؛ اما گزینهٔ -i به‌جای آن، input-file داده‌شده را باز می‌کند. توجه داشته باشید که فایل ورودی می‌تواند به‌عنوان آخرین مؤلفه در خط فرمان نیز مشخص شود.

-e

ترتیب بایت‌ها (endianness) فایل را در خروجی نمایش می‌دهد. دستور trace-cmd report به‌اندازهٔ کافی هوشمند است تا بتواند فایل‌های big-endian را روی ماشین‌های little-endian بخواند و بالعکس.

-f

فهرست تمام توابعی را که در فایل trace.dat نگاشت شده‌اند در خروجی نمایش می‌دهد. توجه داشته باشید که این فهرست ممکن است شامل توابعی باشد که در ردگیری ظاهر نشده‌اند، زیرا این فهرست شامل نگاشت‌هایی برای ترجمهٔ نشانی‌های توابع به نام آن‌ها است.

-P

فهرست داده‌های «trace_printk()» را در خروجی نمایش می‌دهد. داده‌های خام ردگیری به اشاره‌گرهای ایستا در کرنل اشاره می‌کنند. این داده‌ها باید در فایل trace.dat ذخیره شده باشند.

-E

رویدادهای احتمالی موجود در فایل را فهرست می‌کند (اما این فهرست لزوماً فهرست قطعی رویدادهای موجود در فایل نیست).

--events

قالب‌های رویداد ذخیره‌شده در فایل trace.dat را فهرست می‌کند.

--event regex

رویدادهایی را که با regex داده‌شده مطابقت دارند چاپ می‌کند. در صورت مشخص شدن دو‌نقطه (:)، نویسه‌های قبل از دونقطه برای تطابق با سامانه (system) و نویسه‌های بعد از آن برای تطابق با رویداد (event) به کار می‌روند. 
trace-cmd report --event sys:read
دستور بالا فقط با رویدادهایی مطابقت دارد که نام سامانهٔ آن‌ها شامل "sys"
و نام رویداد شامل "read" باشد.
trace-cmd report --event read
دستور بالا با تمام رویدادهایی که نامشان شامل "read" است مطابقت خواهد داشت. همچنین
ممکن است تمام رویدادهای سامانه‌ای را که نام آن شامل "read" است نیز فهرست کند.

--check-events

رشته‌های قالب رویداد ذخیره‌شده در فایل trace.dat را تجزیه کرده و اعلام می‌کند که آیا این قالب‌ها می‌توانند به درستی تجزیه شوند یا خیر. این گزینه افزونه‌ها را بارگذاری می‌کند، مگر آنکه -N مشخص شده باشد.

-t

برچسب زمانی (timestamp) کامل را چاپ می‌کند. برچسب‌های زمانی در فایل داده معمولاً با دقت نانوثانیه ضبط می‌شوند، اما نمایش پیش‌فرض برچسب زمانی فقط تا دقت میکروثانیه است. برای مشاهدهٔ برچسب زمانی کامل، گزینهٔ -t را اضافه کنید.

-F filter

افزودن فیلتر برای محدود کردن رویدادهای نمایش‌داده‌شده. فیلترهایی که پس از یک فایل ورودی (مشخص‌شده با -i) تعریف می‌شوند تنها بر همان فایل ورودی اعمال می‌گردند. فیلترهایی که قبل از ذکر هرگونه فایل ورودی ارائه شوند عمومی تلقی شده و به تمام فایل‌های ورودی اعمال می‌گردند. 
قالب فیلتر به این صورت است:
<events> ':' <filter>
<events> = SYSTEM'/'EVENT  | SYSTEM | EVENT | <events> ',' <events>
<filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> |
           <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
<op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
       '+' | '-' | '*' | '/' | '%'
<value> = NUM | STRING | EVENT_FIELD
عبارت SYSTEM نام سامانه‌ای است که فیلتر بر روی آن اعمال می‌شود. اگر EVENT ذکر نشود،
فیلتر بر تمام رویدادهای ذیل آن SYSTEM اعمال خواهد شد. اگر تنها از یک رشته
بدون کاراکتر '/' برای تفکیک بین SYSTEM و EVENT استفاده شود، در این صورت فیلتر
بر روی تمام سامانه‌ها و رویدادهایی که با رشتهٔ داده‌شده مطابقت دارند اعمال خواهد شد.
فاصله‌های خالی نادیده گرفته می‌شوند، به‌طوری که "sched:next_pid==123" معادل "sched : next_pid == 123" است. 
مقدار STRING با نقل‌قول‌های تکی یا جفت تعریف می‌شود (نقل‌قول تکی باید با
نقل‌قول تکی، و جفت با جفت پایان یابد). فاصله‌های خالی درون نقل‌قول‌ها نادیده
گرفته نمی‌شوند.
نمایش یک SYSTEM یا EVENT همچنین می‌تواند یک عبارت باقاعده (regular expression)
تعریف‌شده توسط 'regcomp(3)' باشد.
مقدار EVENT_FIELD نام فیلدی از یک رویداد است که در حال
پالایش (فیلتر) شدن است. اگر رویداد شامل EVENT_FIELD نباشد، آن بخش از
معادله نادرست (false) در نظر گرفته خواهد شد.
-F 'sched : bogus == 1 || common_pid == 2'
عبارت "bogus == 1" همواره به FALSE ارزیابی می‌شود زیرا هیچ رویدادی دارای
فیلدی به نام "bogus" نیست، اما "common_pid == 2" همچنان ارزیابی خواهد شد
زیرا تمام رویدادها دارای فیلد "common_pid" هستند. هر رویداد "sched" که
توسط فرایندی با PID برابر با ۲ ردگیری شده باشد نشان داده خواهد شد.
توجه داشته باشید، EVENT_FIELD نام فیلدی است که توسط قالب رویداد نشان داده می‌شود
(همان‌طور که با *--events* نمایش داده می‌شود)، نه آنچه در خروجی یافت می‌شود.
اگر خروجی "ID:foo" را نشان دهد اما فیلدی که "foo" به آن تعلق دارد در قالب رویداد
"name" نامیده شده باشد، باید از "name" در فیلتر استفاده شود.
همین امر درباره مقادیر نیز صادق است. اگر مقدار نمایش‌داده‌شده به یک نماد
رشته‌ای تبدیل شده باشد، فیلتر مقدار اصلی را بررسی می‌کند و نه مقدار نمایش‌داده‌شده را.
برای مثال، جهت فیلتر کردن روی تمام وظایفی که در هنگام تعویض زمینه (context switch) در وضعیت در حال اجرا بودند:
-F 'sched/sched_switch : prev_state==0'
اگرچه خروجی 'R' را نمایش می‌دهد، اما داشتن 'prev_stat=="R"' کار نخواهد کرد.
نکته: شما همچنین می‌توانید 'COMM' را به عنوان یک EVENT_FIELD مشخص کنید. این کار از
نام وظیفه (یا comm) رکورد برای مقایسه استفاده می‌کند. برای مثال، برای فیلتر کردن و کنار گذاشتن
تمام وظایف "trace-cmd":
-F '.*:COMM != "trace-cmd"'

-I

رویدادهایی را که پرچم تأخیر HARDIRQ در آن‌ها تنظیم شده است، چاپ نکن. این گزینه بیشتر رویدادهایی را که از زمینه وقفه (interrupt context) هستند فیلتر می‌کند. توجه داشته باشید، ممکن است توابع ردگیری‌شده‌ای را که در زمینه وقفه هستند اما پیش از تنظیم پرچم "in interrupt" هسته فراخوانی شده‌اند، فیلتر نکند.

-S

رویدادهایی را که پرچم تأخیر SOFTIRQ در آن‌ها تنظیم شده است، چاپ نکن. این گزینه بیشتر رویدادهایی را که از زمینه وقفه نرم‌افزاری (soft interrupt context) هستند فیلتر می‌کند.

-v

این گزینه باعث می‌شود که فیلترهای پس از -F رویدادهای منطبق را فیلتر کرده و کنار بگذارند.
-v -F 'sched/sched_switch : prev_state == 0'
هیچ رویداد sched_switch را که دارای prev_state برابر با 0 باشد نمایش نخواهد داد.
حذف کردن *-v* باعث می‌شود که تنها همان رویدادها چاپ شوند.

-T

فیلترهای -F را آزمایش کن. پس از پردازش یک رشته فیلتر، فیلتر حاصل برای هر رویداد نمایش داده خواهد شد. این قابلیت برای استفاده از یک فیلتر برای بیش از یک رویداد که ممکن است فیلدی در همه رویدادها وجود نداشته باشد، مفید است. همچنین می‌توان از آن برای اطمینان از نبود غلط املایی در نام فیلدهای رویداد استفاده کرد، زیرا آن‌ها صرفاً نادیده گرفته خواهند شد. در صورتی که -F مشخص نشده باشد، -T نادیده گرفته می‌شود.

-V

نمایش پیام‌های پرجزئیات (مشاهده کنید --verbose اما فقط برای اعداد)

-L

پلاگین‌های سراسری سیستم را بارگذاری نخواهد کرد. این گزینه فقط پلاگین‌ها را به‌صورت محلی («local only») بارگذاری می‌کند؛ یعنی آنچه را که در دایرکتوری ~/.trace-cmd/plugins می‌یابد. -N
این گزینه هیچ افزونه‌ای را بارگذاری نمی‌کند.

-n event-re

این گزینه باعث می‌شود تمام رویدادهایی که با این گزینه مطابقت دارند، هرگونه کنترل‌کنندهٔ ثبت‌شده (توسط افزونه‌ها) برای چاپ رویداد را نادیده بگیرند. در عوض، رویداد عادی چاپ خواهد شد. آرگومان event-re یک عبارت منظم مطابق با تعریف regcomp(3) است.

--profile

با گزینهٔ --profile ، دستور «trace-cmd report» ابتدا تمام رویدادها را پردازش کرده و سپس قالبی را خروجی می‌دهد که نشان می‌دهد وظایف زمان خود را در کجای هسته صرف کرده‌اند، و همچنین در کجا بیشترین انسداد را داشته‌اند و تأخیرهای بیدارباش (wake up latencies) در کجا قرار دارند. 
برای جزئیات و مثال‌های بیشتر، trace-cmd-profile(1) را ببینید.

-G

تنظیم رویدادهای وقفه (نرم و سخت) به صورت سراسری (وابسته به CPU به جای وظایف). این گزینه فقط برای --profile کار می‌کند.

-H event-hooks

افزودن تطبیق رویداد سفارشی برای پیوند دادن هر دو رویداد به یکدیگر. 
برای ساختار، trace-cmd-profile(1) را ببینید.

-R

این گزینه رویدادها را در قالب «خام» (raw) نشان می‌دهد؛ بدین معنا که قالب‌بندی چاپ رویداد نادیده گرفته شده و صرفاً محتویات هر فیلد چاپ می‌شود.

-r event-re

این گزینه باعث می‌شود تمام رویدادهایی که با این گزینه مطابقت دارند، فیلدهای خام خود را چاپ کنند. آرگومان event-re یک عبارت منظم مطابق با تعریف regcomp(3) است.

-l

این گزینه یک قالب «خروجی تأخیر» (latency output) اضافه می‌کند. اطلاعات مربوط به غیرفعال بودن وقفه‌ها، غیرفعال بودن soft irq، تنظیم بودن پرچم «need_resched»، شمارندهٔ پیش‌دستی (preempt count) و قفل بزرگ هسته (big kernel lock) همگی با هر رویداد ثبت می‌شوند. اما در حالت پیش‌فرض، این اطلاعات نمایش داده نمی‌شوند. این گزینه نمایش این اطلاعات را با ۶ نویسه تنظیم می‌کند. هنگامی که یکی از فیلدها صفر یا N/A باشد، یک '.\' نشان داده می‌شود.
<idle>-0       0d.h1. 106467.859747: function:             ktime_get <-- tick_check_idle
عبارت 0d.h1. این اطلاعات را نشان می‌دهد.
با یک عدد شروع می‌شود. این نشان‌دهندهٔ شماره CPU است که رویداد روی آن رخ
داده است.
نویسهٔ دوم یکی از موارد زیر است:
'd' - وقفه‌ها غیرفعال هستند
'.' - وقفه‌ها فعال هستند
'X' - دارای پرچم‌هایی است که هنوز برای trace-cmd شناخته‌شده نیستند
نویسهٔ سوم پرچم «نیاز به زمان‌بندی مجدد» (need rescheduling) است.
'N' - یک زمان‌بندی برای اجرا تنظیم شده است
'.' - هیچ زمان‌بندی‌ای تنظیم نشده است
نویسهٔ چهارم نشان‌دهندهٔ بافتی است که رویداد هنگام رخ دادن در آن قرار داشته است
'h' - بافت وقفه سخت‌افزاری
's' - بافت وقفه نرم‌افزاری
'H' - بافت وقفه سخت‌افزاری که یک وقفه نرم‌افزاری را قطع کرده است
'.' - بافت عادی
مورد بعدی یک عدد است (باید کمتر از ۱۰ باشد) که عمق پیش‌دستی (preemption depth) را
نشان می‌دهد (تعداد دفعاتی که preempt_disable() بدون preempt_enable() فراخوانی شده است).
'.' به معنای فعال بودن پیش‌دستی است.
در برخی سامانه‌ها، ممکن است «migrate disable» وجود داشته باشد، که در این حالت عددی برای آن نمایش داده می‌شود، یا '.' به معنای فعال بودن مهاجرت (migration) است. 
اگر lockdep روی سامانه فعال باشد، عدد نشان‌دهنده عمق قفل‌هایی است که
هنگام تحریک رویداد نگه‌داشته شده‌اند. '.' به معنای عدم نگهداری هیچ قفلی است.

-w

اگر هر دو رویداد sched_switch و sched_wakeup فعال باشند، این گزینه تأخیر زمانی بین نخستین بیداری تسک و زمان زمان‌بندی شدن آن را گزارش می‌دهد.

-q

بی‌صدا کردن هشدارهای غیربحرانی.

-O

ارسال گزینه‌ها به افزونه‌های بارگذاری‌شده trace-cmd. 
-O plugin:var=value
عبارت‌های 'plugin:' و '=value' اختیاری هستند. برای گزینه‌های بولی
(boolean) می‌توان مقدار را نادیده گرفت. اگر 'plugin:' حذف شود،
هر متغیری که در تمام افزونه‌ها مطابقت داشته باشد تنظیم خواهد شد.
مثال:  -O fgraph:tailprint

--cpu <cpu list>

فهرستی از پردازنده‌ها، جدا شده با «,» یا «:»، که برای فیلتر کردن رویدادها به کار می‌رود. بازه‌ای از پردازنده‌ها را می‌توان با استفاده از نمادگذاری «cpuX-cpuY» مشخص کرد، که در آن تمام پردازنده‌های موجود در بازه میان cpuX و cpuY در فهرست گنجانده می‌شوند. ترتیب پردازنده‌ها در این فهرست باید از کوچک‌تر به بزرگ‌تر باشد. 
مثال:  "--cpu 0,3" - نمایش رویدادها از پردازنده‌های 0 و 3
       "--cpu 2-4" - نمایش رویدادها از پردازنده‌های 2، 3 و 4

--cpus

فهرست کردن پردازنده‌هایی که در فایل ردگیری داده دارند و سپس خروج.

--first-event

نمایش برچسب زمانی نخستین رویداد از تمامی پردازنده‌هایی که داده دارند.

--last-event

نمایش برچسب زمانی آخرین رویداد از تمامی پردازنده‌هایی که داده دارند.

--stat

اگر فایل trace.dat آمار نهایی (که در پایان ضبط خروجی داده شده) را ذخیره کرده باشد، می‌توان از گزینه --stat برای بازیابی آن‌ها استفاده کرد.

--uname

اگر فایل trace.dat اطلاعات uname را در حین اجرا ضبط کرده باشد، این گزینه آن اطلاعات را بازیابی می‌کند.

--version

اگر فایل trace.dat نگارش فایل اجرایی استفاده‌شده برای ایجاد آن را ضبط کرده باشد، آن نگارش را گزارش می‌دهد.

--ts-offset offset

افزودن (یا در صورت منفی بودن، کسر کردن) یک آفست (انحراف) به تمامی برچسب‌های زمانی فایل داده قبلی مشخص‌شده با -i. این قابلیت برای مرتب‌سازی ادغامی چندین فایل trace.dat که اختلاف برچسب‌های زمانی آن‌ها مشخص است سودمند است. برای نمونه، اگر ردگیری روی یک مهمان مجازی انجام شده باشد و ردگیری دیگری روی میزبان صورت گیرد؛ چنانچه برچسب زمانی میزبان 1000 واحد جلوتر از مهمان باشد، می‌توان دستور زیر را به کار برد: 
trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat
این دستور هنگام ادغام با رویدادهای guest.dat، مقدار 1000 واحد زمانی را از
تمامی رویدادهای میزبان کسر می‌کند. توجه داشته باشید که این واحدها، واحدهای
خام ثبت‌شده در ردگیری هستند. اگر واحدها نانوثانیه باشند، عمل جمع (یا تفریق)
آفست برحسب نانوثانیه خواهد بود، حتی اگر واحدهای نمایش‌داده‌شده میکروثانیه باشند.

--ts2secs HZ

تبدیل منبع ساعت جاری به یک خروجی برحسب ثانیه (با تفکیک‌پذیری نانوثانیه). هنگام استفاده از ساعت‌هایی چون x86-tsc، در صورتی که بسامد (فرکانس) مشخص باشد، با مشخص کردن فرکانس ساعت، این گزینه زمان را به ثانیه تبدیل می‌کند. 
این گزینه بر روی هر فایل trace.dat که پس از آن با *-i* مشخص شود تأثیر می‌گذارد.
اگر این گزینه پیش از هر گزینه *-i* قرار گیرد، آن مقدار به ضریب تبدیل
پیش‌فرض برای تمام فایل‌های دیگر trace.dat بدل خواهد شد. اگر گزینه --ts2secs
دیگری پس از یک فایل trace.dat همراه با *-i* ظاهر شود، آن گزینه مقدار
پیش‌فرض را بازنویسی می‌کند.
مثال: روی یک رایانه 3.4 گیگاهرتزی
trace-cmd record -p function -C x86-tsc
trace-cmd report --ts2ns 3400000000
گزارش، برچسب‌های زمانی چرخه‌ها (cycles) را به یک نمایش ثانیه‌ای خوانا
تبدیل خواهد کرد. تفکیک‌پذیری پیش‌فرض نمایش، میکروثانیه است، مگر اینکه از *-t*
استفاده شود.
مقدار --ts-offset حتی با این گزینه نیز همچنان باید در واحدهای برچسب زمانی خام
باشد. این آفست نیز تبدیل خواهد شد.

--ts-diff

اختلاف زمانی میان رویدادها را نشان می‌دهد. این اختلاف درون پرانتز درست پس از برچسب زمانی نمایش داده خواهد شد.

--ts-check

اطمینان حاصل می‌کند که هیچ برچسب زمانی به عقب بازنگردد، و در صورت رخ دادن، یک پیام هشدار مبنی بر این موضوع چاپ می‌کند.

--nodate

از تبدیل برچسب‌های زمانی به تاریخ تعیین‌شده توسط گزینه --date در trace-cmd record(3) صرف‌نظر می‌کند.

--raw-ts

نمایش برچسب‌های زمانی خام، بدون اعمال هرگونه تصحیح.

--align-ts

نمایش برچسب‌های زمانی تراز‌شده با نخستین رویداد.

--verbose[=level]

سطح گزارش‌گیری را تنظیم می‌کند. سطوح گزارش‌گیری پشتیبانی‌شده عبارتند از "none"، "crit"، "err"، "warn"، "info"، "debug"، "all" یا شناسه‌های آن‌ها "0"، "1"، "2"، "3"، "4"، "5"، "6". تنظیم سطح گزارش‌گیری روی یک مقدار خاص، تمامی گزارش‌های آن سطح و تمام سطوح پیشین را فعال می‌کند. در صورتی که سطحی مشخص نشود، مقدار پیش‌فرض "info" خواهد بود. 
مثال: فعال‌سازی تمام لاگ‌های بحرانی، خطا و هشدار
trace-cmd report --verbose=warning

با استفاده از یک فایل trace.dat که با دستور زیر ایجاد شده است:

# trace-cmd record -p function -e all sleep 5

گزارش پیش‌فرض نشان می‌دهد:

 # trace-cmd report
cpus=8
           sleep-89142 [001] ...1. 162573.215752: function:             mutex_unlock
           sleep-89142 [001] ...1. 162573.215754: function:             __mutex_unlock_slowpath
           sleep-89142 [001] ..... 162573.215755: lock_release:         0xffffffff855e7448 trace_types_lock
           sleep-89142 [001] ..... 162573.215757: lock_release:         0xffff892a01b54420 sb_writers
           sleep-89142 [001] ...1. 162573.215757: function:             preempt_count_add
           sleep-89142 [001] ...1. 162573.215758: preempt_disable:      caller=vfs_write+0x147 parent=vfs_write+0x147
           sleep-89142 [001] ...2. 162573.215758: function:             rcu_read_lock_any_held
           sleep-89142 [001] ...2. 162573.215759: function:                rcu_lockdep_current_cpu_online
           sleep-89142 [001] ...2. 162573.215759: function:             preempt_count_sub
           sleep-89142 [001] ...1. 162573.215760: preempt_enable:       caller=vfs_write+0x176 parent=vfs_write+0x176
           sleep-89142 [001] ...1. 162573.215761: function:             __f_unlock_pos
           sleep-89142 [001] ...1. 162573.215761: function:             mutex_unlock
[...]

نکته در مورد ستون سوم:

 sleep-89998 [002] ...1. 223087.004011: lock_acquire:         0xffff892b7cf32c20 lock
 sleep-89998 [002] ...1. 223087.004011: lock_acquire:         0xffffffff85517f00 read rcu_read_lock
<idle>-0     [005] dNh2. 223087.004012: sched_wakeup:         trace-cmd:89992 [120] CPU:005
 sleep-89998 [002] ...1. 223087.004012: lock_acquire:         0xffffffff85517f00 read rcu_read_lock
 sleep-89998 [002] ...1. 223087.004013: lock_release:         0xffffffff85517f00 rcu_read_lock

این ستون از همان ساختاری پیروی می‌کند که در فایل /sys/kernel/tracing/trace در هسته لینوکس نشان داده شده است.

# cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:8
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |

مشابه توضیحات داده‌شده در گزینه -l است. به‌طوری که موقعیت نخست:

'.' - به معنی فعال بودن وقفه‌ها و bottom halfها است
'd' - به معنی غیرفعال بودن وقفه‌ها و bottom halfها است

موقعیت دوم:

'N' - به این معنی است که پرچم "NEED_RESCHED" تنظیم شده و هسته باید
      در سریع‌ترین زمان ممکن زمان‌بندی را انجام دهد.

موقعیت سوم:

'.' - در زمینه عادی/قابل زمان‌بندی
's' - در زمینه وقفه نرم‌افزاری (soft interrupt)
'h' - در زمینه وقفه سخت‌افزاری (hard interrupt)
'H' - در زمینه وقفه سخت‌افزاری که یک وقفه نرم‌افزاری را قطع کرده است

جایگاه چهارم عمق preempt count است:

'pass:[.]' - قابلیت preemption فعال است
'#' - عمق غیرفعال بودن preemption (تودرتو)

ستون پنجم شمارنده غیرفعال بودن مهاجرت (migration disabled counter) است:

'.' - مهاجرت (migration) فعال است
'#' - عمق غیرفعال بودن مهاجرت (تودرتو)

برای دیدن همه‌چیز به‌جز ردگیری‌های تابع (function):

 # trace-cmd report -v -F 'function'
cpus=8
           sleep-89142 [001] ..... 162573.215755: lock_release:         0xffffffff855e7448 trace_types_lock
           sleep-89142 [001] ..... 162573.215757: lock_release:         0xffff892a01b54420 sb_writers
           sleep-89142 [001] ...1. 162573.215758: preempt_disable:      caller=vfs_write+0x147 parent=vfs_write+0x147
           sleep-89142 [001] ...1. 162573.215760: preempt_enable:       caller=vfs_write+0x176 parent=vfs_write+0x176
           sleep-89142 [001] ..... 162573.215762: lock_release:         0xffff892a19601ac8 &f->f_pos_lock
           sleep-89142 [001] ..... 162573.215764: sys_exit:             NR 1 = 1
           sleep-89142 [001] ..... 162573.215766: sys_exit_write:       0x1
           sleep-89142 [001] d.... 162573.215767: irq_disable:          caller=syscall_exit_to_user_mode+0x15 parent=0x0
           sleep-89142 [001] d.... 162573.215768: irq_enable:           caller=syscall_exit_to_user_mode+0xed parent=0x0
           sleep-89142 [001] ..... 162573.215773: lock_acquire:         0xffff892a4ad29318 read &mm->mmap_lock
           sleep-89142 [001] ..... 162573.215775: lock_release:         0xffff892a4ad29318 &mm->mmap_lock
           sleep-89142 [001] ..... 162573.215778: lock_acquire:         0xffff892a4ad29318 read &mm->mmap_lock
[...]

برای مشاهده تنها فراخوانی‌های kmalloc که بزرگ‌تر از ۱۰۰۰ بایت بوده‌اند:

 # trace-cmd report -F 'kmalloc: bytes_req > 1000'
cpus=8
           sleep-89142 [001] ..... 162573.219401: kmalloc:              (tomoyo_find_next_domain+0x84) call_site=tomoyo_find_next_domain+0x84 ptr=0xffff892a176c0000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xd40 node=-1 accounted=false
           sleep-89142 [001] ..... 162573.219511: kmalloc:              (tomoyo_realpath_from_path+0x42) call_site=tomoyo_realpath_from_path+0x42 ptr=0xffff892a176c6000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xc40 node=-1 accounted=false
       trace-cmd-89135 [000] ..... 162573.244301: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89135 [000] ..... 162573.244471: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89134 [007] ..... 162573.267148: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89134 [007] ..... 162573.267403: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89141 [002] ..... 162573.290583: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89141 [002] ..... 162573.290754: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89139 [004] ..... 162573.784636: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63d70000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
[...]
برای مشاهده بیدارباش‌ها (wakeups) و تعویض‌های sched که تسک قبلی را در وضعیت running باقی گذاشته‌اند: 
 # trace-cmd report -F 'sched: prev_state == 0' -F 'sched_waking'
cpus=8
           sleep-89142 [001] d.h6. 162573.215941: sched_waking:         comm=trace-cmd pid=89135 prio=120 target_cpu=000
          <idle>-0     [000] dNh7. 162573.216219: sched_waking:         comm=trace-cmd pid=89134 prio=120 target_cpu=007
          <idle>-0     [000] d..2. 162573.216423: sched_switch:         swapper/0:0 [120] R ==> trace-cmd:89135 [120]
          <idle>-0     [007] dNh7. 162573.216511: sched_waking:         comm=trace-cmd pid=89141 prio=120 target_cpu=002
          <idle>-0     [007] d..2. 162573.216698: sched_switch:         swapper/7:0 [120] R ==> trace-cmd:89134 [120]
          <idle>-0     [002] dNh7. 162573.216776: sched_waking:         comm=trace-cmd pid=89136 prio=120 target_cpu=001
          <idle>-0     [002] d..2. 162573.216951: sched_switch:         swapper/2:0 [120] R ==> trace-cmd:89141 [120]
           sleep-89142 [001] d.s3. 162573.231260: sched_waking:         comm=rcu_preempt pid=17 prio=120 target_cpu=002
          <idle>-0     [002] d..2. 162573.231568: sched_switch:         swapper/2:0 [120] R ==> rcu_preempt:17 [120]
           sleep-89142 [001] d.s2. 162573.240425: sched_waking:         comm=rcu_preempt pid=17 prio=120 target_cpu=002
          <idle>-0     [002] d..2. 162573.240719: sched_switch:         swapper/2:0 [120] R ==> rcu_preempt:17 [120]
           sleep-89142 [001] d.h7. 162573.241983: sched_waking:         comm=trace-cmd pid=89135 prio=120 target_cpu=000

مورد بالا به کمی توضیح نیاز دارد. فیلتر، زیرسیستم «sched» را مشخص می‌کند که شامل تمام رویدادهای زمان‌بندی است. هر رویدادی که فیلد قالبی «prev_state» را نداشته باشد، آن عبارات را FALSE ارزیابی می‌کند و هیچ تطابقی تولید نخواهد کرد. تنها رویداد sched_switch با آن تطابق خواهد داشت. گزینه دوم «-F» رویداد sched_waking را در بر خواهد گرفت.

  # trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
[...]
       trace-cmd-89141 [007] d..2. 162583.263060: sched_switch:         trace-cmd:89141 [120] R ==> trace-cmd:89135 [120]
   kworker/u36:1-51219 [000] d..2. 162583.266957: sched_switch:         kworker/u36:1:51219 [120] R ==> kworker/u33:2:49692 [120] Latency: 4024.977 usecs
       trace-cmd-89135 [007] d..2. 162583.267109: sched_switch:         trace-cmd:89135 [120] R ==> trace-cmd:89141 [120]
       trace-cmd-89139 [001] d..2. 162583.267147: sched_switch:         trace-cmd:89139 [120] D ==> swapper/1:0 [120]
   kworker/u36:2-88857 [002] d..2. 162583.267913: sched_switch:         kworker/u36:2:88857 [120] R ==> trace-cmd:89136 [120]
   kworker/u33:2-49692 [000] d..2. 162583.268334: sched_switch:         kworker/u33:2:49692 [120] I ==> kworker/u36:1:51219 [120]
          <idle>-0     [001] dNh4. 162583.268747: sched_wakeup:         sleep:89142 [120] CPU:001
          <idle>-0     [001] d..2. 162583.268833: sched_switch:         swapper/1:0 [120] R ==> sleep:89142 [120] Latency: 85.751 usecs
           sleep-89142 [001] d.h4. 162583.269022: sched_wakeup:         trace-cmd:89139 [120] CPU:001
       trace-cmd-89141 [007] d..2. 162583.271009: sched_switch:         trace-cmd:89141 [120] R ==> trace-cmd:89135 [120]
       trace-cmd-89136 [002] d..2. 162583.271020: sched_switch:         trace-cmd:89136 [120] R ==> kworker/u36:2:88857 [120]
   kworker/u36:2-88857 [002] d..2. 162583.271079: sched_switch:         kworker/u36:2:88857 [120] I ==> trace-cmd:89136 [120]
       trace-cmd-89137 [006] d.h2. 162583.273950: sched_wakeup:         trace-cmd:89133 [120] CPU:006
           sleep-89142 [001] d..2. 162583.274064: sched_switch:         sleep:89142 [120] Z ==> trace-cmd:89139 [120] Latency: 5042.285 usecs
       trace-cmd-89135 [007] d..2. 162583.275043: sched_switch:         trace-cmd:89135 [120] R ==> trace-cmd:89141 [120]
       trace-cmd-89137 [006] d..2. 162583.275158: sched_switch:         trace-cmd:89137 [120] R ==> trace-cmd:89133 [120] Latency: 1207.327 usecs
       trace-cmd-89136 [002] dNh3. 162583.275229: sched_wakeup:         rcu_preempt:17 [120] CPU:002
       trace-cmd-89136 [002] d..2. 162583.275294: sched_switch:         trace-cmd:89136 [120] R ==> rcu_preempt:17 [120] Latency: 65.255 usecs
     rcu_preempt-17    [002] d..2. 162583.275399: sched_switch:         rcu_preempt:17 [120] I ==> trace-cmd:89136 [120]
Average wakeup latency: 20082.580 usecs
Maximum Latency: 1032049.277 usecs at timestamp: 162574.787022
Minimum Latency: 29.023 usecs at timestamp: 162583.189731
RT task timings:
Average wakeup latency: 139.568 usecs
Maximum Latency: 220.583 usecs at timestamp: 162577.347038
Minimum Latency: 75.902 usecs at timestamp: 162577.719121

ردیابی بالا زمان‌های تأخیر بیدارباش (wakeup latencies) تسک‌ها را تولید می‌کند. رویداد «sched_switch» هر تأخیر مجزا را پس از نوشتن اطلاعات رویداد گزارش می‌دهد. در انتهای گزارش، میانگین تأخیر بیدارباش، و همچنین بیشترین و کمترین تأخیر همراه با برچسب زمانیِ رخ دادن آن‌ها گزارش می‌شود. این کار هم برای تسک‌های عادی و هم برای تسک‌های بلادرنگ (real-time) انجام می‌گیرد.

  # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
cpus=8
          <idle>-0     [001] dNh5. 162573.291142: sched_wakeup:         migration/1:23 [0] CPU:001
          <idle>-0     [001] d..2. 162573.291237: sched_switch:         swapper/1:0 [120] R ==> migration/1:23 [0] Latency: 94.643 usecs
       trace-cmd-89141 [002] dNh6. 162573.346785: sched_wakeup:         migration/2:28 [0] CPU:002
       trace-cmd-89141 [002] d..2. 162573.346929: sched_switch:         trace-cmd:89141 [120] R ==> migration/2:28 [0] Latency: 143.971 usecs
       trace-cmd-89134 [003] dNh4. 162573.410852: sched_wakeup:         migration/3:33 [0] CPU:003
       trace-cmd-89134 [003] d..2. 162573.411039: sched_switch:         trace-cmd:89134 [120] R ==> migration/3:33 [0] Latency: 187.640 usecs
          <idle>-0     [004] dNh5. 162573.490944: sched_wakeup:         migration/4:38 [0] CPU:004
          <idle>-0     [004] d..2. 162573.491098: sched_switch:         swapper/4:0 [120] R ==> migration/4:38 [0] Latency: 153.913 usecs
          <idle>-0     [005] dNh5. 162573.574955: sched_wakeup:         migration/5:43 [0] CPU:005
          <idle>-0     [005] d..2. 162573.575107: sched_switch:         swapper/5:0 [120] R ==> migration/5:43 [0] Latency: 152.875 usecs
          <idle>-0     [006] dNh5. 162573.646878: sched_wakeup:         migration/6:48 [0] CPU:006
          <idle>-0     [006] d..2. 162573.646992: sched_switch:         swapper/6:0 [120] R ==> migration/6:48 [0] Latency: 113.788 usecs
       trace-cmd-89140 [002] dNh7. 162577.346818: sched_wakeup:         migration/2:28 [0] CPU:002
       trace-cmd-89140 [002] d..2. 162577.347038: sched_switch:         trace-cmd:89140 [120] R ==> migration/2:28 [0] Latency: 220.583 usecs
       trace-cmd-89134 [003] dNh5. 162577.410869: sched_wakeup:         migration/3:33 [0] CPU:003
       trace-cmd-89141 [005] dNh6. 162577.574792: sched_wakeup:         migration/5:43 [0] CPU:005
       trace-cmd-89141 [005] d..2. 162577.574915: sched_switch:         trace-cmd:89141 [120] R ==> migration/5:43 [0] Latency: 122.648 usecs
       trace-cmd-89136 [007] dNh6. 162577.719045: sched_wakeup:         migration/7:53 [0] CPU:007
       trace-cmd-89136 [007] d..2. 162577.719121: sched_switch:         trace-cmd:89136 [120] R ==> migration/7:53 [0] Latency: 75.902 usecs
       trace-cmd-89140 [005] dNh4. 162581.574827: sched_wakeup:         migration/5:43 [0] CPU:005
       trace-cmd-89140 [005] d..2. 162581.574957: sched_switch:         trace-cmd:89140 [120] R ==> migration/5:43 [0] Latency: 129.717 usecs
   kworker/u46:1-51211 [006] dNh4. 162581.646809: sched_wakeup:         migration/6:48 [0] CPU:006
Average wakeup latency: 139.568 usecs
Maximum Latency: 220.583 usecs at timestamp: 162577.347038
Minimum Latency: 75.902 usecs at timestamp: 162577.719121
RT task timings:
Average wakeup latency: 139.568 usecs
Maximum Latency: 220.583 usecs at timestamp: 162577.347038
Minimum Latency: 75.902 usecs at timestamp: 162577.719121

نسخه بالا فقط بیدارباش‌ها و تعویض‌های زمینه (context switches) تسک‌های Real Time را نشان خواهد داد. مقدار prio استفاده‌شده در داخل هسته، از 0 برای بالاترین اولویت آغاز می‌شود. بدین معنا که prio معادل 0 برابر با اولویت بلادرنگ ۹۹ در فضای کاربری (user space)، و اولویت ۹۸ معادل با اولویت بلادرنگ ۱ در فضای کاربری است. مقادیر prio کمتر از 100 نمایانگر تسک‌های Real Time هستند. توجه داشته باشید که زمان‌های کلی بیدارباش با زمان‌های تسک‌های RT یکسان هستند.

نمونه‌ای از profile:

 # trace-cmd record --profile sleep 1
 # trace-cmd report --profile --comm sleep
task: sleep-21611
  Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
     <stack> 1 total:99442 min:99442 max:99442 avg=99442
       => ftrace_raw_event_sched_switch (0xffffffff8105f812)
       => __schedule (0xffffffff8150810a)
       => preempt_schedule (0xffffffff8150842e)
       => ___preempt_schedule (0xffffffff81273354)
       => cpu_stop_queue_work (0xffffffff810b03c5)
       => stop_one_cpu (0xffffffff810b063b)
       => sched_exec (0xffffffff8106136d)
       => do_execve_common.isra.27 (0xffffffff81148c89)
       => do_execve (0xffffffff811490b0)
       => SyS_execve (0xffffffff811492c4)
       => return_to_handler (0xffffffff8150e3c8)
       => stub_execve (0xffffffff8150c699)
  Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
     <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
       => ftrace_raw_event_sched_switch (0xffffffff8105f812)
       => __schedule (0xffffffff8150810a)
       => schedule (0xffffffff815084b8)
       => do_nanosleep (0xffffffff8150b22c)
       => hrtimer_nanosleep (0xffffffff8108d647)
       => SyS_nanosleep (0xffffffff8108d72c)
       => return_to_handler (0xffffffff8150e3c8)
       => tracesys_phase2 (0xffffffff8150c304)
  Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
     <stack> 1 total:30326 min:30326 max:30326 avg=30326
       => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
       => ttwu_do_wakeup (0xffffffff810606eb)
       => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
       => try_to_wake_up (0xffffffff8106340a)

trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1), trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1), trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1), trace-cmd-profile(1)

نوشته‌شده توسط Steven Rostedt، <rostedt@goodmis.org[1]>

https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git

کپی‌رایت (C) 2010 متعلق به Red Hat, Inc. استفاده آزاد از این نرم‌افزار تحت شرایط مجوز عمومی همگانی گنو (GPL) مجاز است.

1.
rostedt@goodmis.org
mailto:rostedt@goodmis.org
03/09/2026 libtracefs