{"id":148,"date":"2010-12-19T11:20:28","date_gmt":"2010-12-19T11:20:28","guid":{"rendered":"http:\/\/wp.neependra.net\/?p=148"},"modified":"2010-12-19T11:20:28","modified_gmt":"2010-12-19T11:20:28","slug":"ftrace-fedora-mini-conf-session-at-foss-in10","status":"publish","type":"post","link":"https:\/\/neependra.net\/index.php\/2010\/12\/19\/ftrace-fedora-mini-conf-session-at-foss-in10\/","title":{"rendered":"Ftrace: Fedora Mini-Conf Session at FOSS.in\u201910"},"content":{"rendered":"

I gave a talk on Ftrace in Fedora Mini-Conf\u00a0 at FOSS.in’10.<\/a><\/p>\n

The slides are at https:\/\/fedoraproject.org\/wiki\/File:Fedora_Ftrace.pdf<\/a><\/p>\n

I started my presentation with an example. I setup function_ftrace<\/strong><\/em> as\u00a0 current_tracer <\/strong><\/em>and set<\/p>\n

the trace filter for all the ext3<\/strong><\/em> functions and started the tracing:<\/p>\n

[sourcecode language=”text” gutter=”false”]<\/p>\n

$ echo function_ftrace > \/sys\/kernel\/debug\/tracing\/current_tracer<\/p>\n

$ echo ext3* > \/sys\/kernel\/debug\/tracing\/set_ftrace_filter<\/p>\n

$ echo 1\u00a0 > \/sys\/kernel\/debug\/tracing\/tracing_on<\/p>\n

[\/sourcecode]<\/p>\n

Then after creating a ext3 filesystem, I created a directory on it.<\/p>\n

We got a trace in the \/sys\/kernel\/debug\/tracing\/trace file. A snippet from it :-<\/p>\n

[sourcecode language=”text” gutter=”false”]
\n1) ! 23988.06 us |\u00a0\u00a0\u00a0 } \/* ext3_new_inode *\/
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0\u00a0 \u00a0 |\u00a0\u00a0\u00a0 ext3_bread() {
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0\u00a0 \u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_getblk() {
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_get_blocks_handle() {
\n1)\u00a0\u00a0 0.461 us \u00a0 \u00a0\u00a0 \u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_block_to_path();
\n1)\u00a0\u00a0 0.365 us\u00a0\u00a0 \u00a0 \u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_get_branch();
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_new_blocks() {
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_dirty_inode() {
\n1)\u00a0\u00a0 0.602 us \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_journal_start_sb();
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_mark_inode_dirty() {
\n1)\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 |\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ext3_reserve_inode_write() {
\n[\/sourcecode]<\/p>\n

This kind of stuff helps when you try to understand the kernel code because you know what functions are getting called.<\/p>\n

Second example I took to get the function trace when the system system OOPs. I did following setting to get the trace:-<\/p>\n

[sourcecode language=”text” gutter=”false”]
\necho function_graph > \/sys\/kernel\/debug\/tracing\/current_tracer
\necho 5 > \/sys\/kernel\/debug\/tracing\/buffer_size_kb
\necho 1 > \/sys\/kernel\/debug\/tracing\/tracing_on
\necho 1 > \/proc\/sys\/kernel\/ftrace_dump_on_oops
\n[\/sourcecode]<\/p>\n

I used one\u00a0 simple character driver for that. It can be downloaded from<\/p>\n

http:\/\/wp.neependra.net\/kernel\/char-dev-read-write-oop.tar.gz<\/a><\/p>\n

I had following for the read operation<\/p>\n

[sourcecode language=”cpp” gutter=”false”]
\nstatic ssize_t mycdrv1_read (struct file *file, char __user * buf, size_t lbuf, loff_t * ppos)
\n{
\n*(int *)0 = 0;
\n}
\n[\/sourcecode]<\/p>\n

After inserting the module I created the character device<\/p>\n

[sourcecode language=”text” gutter=”false”]
\ninsmod char-read-write.ko
\nmknod \/dev\/mycdrv1 c 700 0<\/p>\n

[\/sourcecode]<\/p>\n

Just after doing the read to the device OOPs happened and got\u00a0 following in the in the \/var\/log\/messages<\/strong> file<\/p>\n

[sourcecode language=”text” gutter=”false”]
\nmycdrv1_read() {
\n raw_local_irq_enable();
\n ………..
\n find_vma();
\n bad_area() {
\n up_read();
\n …………
\n is_prefetch.clone.13() {
\n convert_ip_to_linear();
\n pagefault_disable();
\n pagefault_enable();
\n }
\n oops_enter() {
\n[\/sourcecode]<\/p>\n

Then I showed an example with sched_switch<\/strong><\/em> tracer and showed how we can trace all the function of a particular module.<\/p>\n

[sourcecode language=”text” gutter=”false”]<\/pre>
\n$ echo sched_switch > \/sys\/kernel\/debug\/tracing\/current_tracer<\/p>\n

$ echo :mod:zfs > \/sys\/kernel\/debug\/tracing\/set_ftrace_filter
\n[\/sourcecode]<\/p>\n

I also also showed how to look at the stack usage.\u00a0 To enable stack strace<\/p>\n

[sourcecode language=”text” gutter=”false”]
\necho 1 > \/proc\/sys\/kernel\/stack_tracer_enabled
\n[\/sourcecode]<\/p>\n

and\u00a0 look at \/sys\/kernel\/debug\/tracing\/stack_trace file, which will have something like.<\/p>\n

[sourcecode language=”text” gutter=”false”]
\nDepth\u00a0\u00a0\u00a0 Size\u00a0\u00a0 Location\u00a0\u00a0\u00a0 (15 entries)
\n—–\u00a0\u00a0\u00a0 —-\u00a0\u00a0 ——–
\n0)\u00a0\u00a0\u00a0\u00a0 1544\u00a0\u00a0\u00a0\u00a0 352\u00a0\u00a0 ext3_get_blocks_handle+0xa0\/0x920
\n1)\u00a0\u00a0\u00a0\u00a0 1192\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\u00a0\u00a0 return_to_handler+0x0\/0x2f
\n2)\u00a0\u00a0\u00a0\u00a0 1192\u00a0\u00a0\u00a0\u00a0\u00a0 96\u00a0\u00a0 ext3_get_block+0xbb\/0xf8
\n3)\u00a0\u00a0\u00a0\u00a0 1096\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\u00a0\u00a0 return_to_handler+0x0\/0x2f
\n4)\u00a0\u00a0\u00a0\u00a0 1096\u00a0\u00a0\u00a0\u00a0 128\u00a0\u00a0 generic_block_bmap+0x3c\/0x42
\n[\/sourcecode]<\/p>\n

It tells you how much kernel stack is used and usage from\u00a0 each function. This was very helpful for me while doing the port<\/p>\n

of ZFS on Linux<\/strong><\/em>.<\/a> We have limited kernel stack on Linux but this not the case in Solaris.<\/p>\n

I then talked about trace-cmd<\/strong><\/em> and kernelshark<\/strong><\/em>.<\/p>\n","protected":false},"excerpt":{"rendered":"

I gave a talk on Ftrace in Fedora Mini-Conf\u00a0 at FOSS.in’10. The slides are at https:\/\/fedoraproject.org\/wiki\/File:Fedora_Ftrace.pdf I started my presentation with an example. I setup function_ftrace as\u00a0 current_tracer and set the trace filter for all the ext3 functions and started the tracing: [sourcecode language=”text” gutter=”false”] $ echo function_ftrace > \/sys\/kernel\/debug\/tracing\/current_tracer $ echo ext3* > \/sys\/kernel\/debug\/tracing\/set_ftrace_filter … Read more<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"om_disable_all_campaigns":false,"_monsterinsights_skip_tracking":false,"_monsterinsights_sitenote_active":false,"_monsterinsights_sitenote_note":"","_monsterinsights_sitenote_category":0,"_jetpack_newsletter_access":"","_jetpack_dont_email_post_to_subs":false,"_jetpack_newsletter_tier_id":0,"_jetpack_memberships_contains_paywalled_content":false,"_jetpack_memberships_contains_paid_content":false,"footnotes":"","jetpack_post_was_ever_published":false},"categories":[48],"tags":[84,86,88,101],"class_list":["post-148","post","type-post","status-publish","format-standard","hentry","category-uncategorized","tag-fedora","tag-foss","tag-ftrace","tag-kernel"],"aioseo_notices":[],"aioseo_head":"\n\t\t\n\t\n\t\n\t\n\t\n\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t\n\t\t