linux-kernel - Re: [PATCH v6] tracing: add additional marks to signal very large time

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Date:	Wed, 3 Dec 2014 04:15:33 -0500
From:	Steven Rostedt <rostedt@...dmis.org>
To:	byungchul.park@....com
Cc:	mingo@...hat.com, linux-kernel@...r.kernel.org,
	seungho1.park@....com, jolsa@...hat.com
Subject: Re: [PATCH v6] tracing: add additional marks to signal very large
 time

On Mon, 24 Nov 2014 09:34:19 +0900
byungchul.park@....com wrote:

> From: Byungchul Park <byungchul.park@....com>
> 
> Currently, function graph tracer prints "!" or "+" just before
> function execution time to signal a function overhead, depending
> on the time. And some tracers tracing latency also print "!" or
> "+" just after time to signal overhead, depending on the interval
> between events. Even it is usually enough to do that, we sometimes
> need to be signaled for bigger execution time than 100 micro seconds.
> 
> For example, I used function graph tracer to detect if there is
> any case that exit_mm() takes too much time. I did following steps
> in /sys/kernel/debug/tracing. It was easier to detect very big
> excution time with patched kernel than with original kernel.
> 
> $ echo exit_mm > set_graph_function
> $ echo function_graph > current_tracer
> $ echo > trace
> $ cat trace_pipe > $LOGFILE
>  ... (do something and terminate logging)
> $ grep "\\$" $LOGFILE
>  3) $ 22082032 us |                      } /* kernel_map_pages */
>  3) $ 22082040 us |                    } /* free_pages_prepare */
>  3) $ 22082113 us |                  } /* free_hot_cold_page */
>  3) $ 22083455 us |                } /* free_hot_cold_page_list */
>  3) $ 22083895 us |              } /* release_pages */
>  3) $ 22177873 us |            } /* free_pages_and_swap_cache */
>  3) $ 22178929 us |          } /* unmap_single_vma */
>  3) $ 22198885 us |        } /* unmap_vmas */
>  3) $ 22206949 us |      } /* exit_mmap */
>  3) $ 22207659 us |    } /* mmput */
>  3) $ 22207793 us |  } /* exit_mm */
> 
> And then, it was easy to find out that a schedule-out occured by
> sub_preempt_count() within kernel_map_pages().
> 
> To detect very large function exection time caused by either problematic
> function implementation or scheduling issues, this patch can be useful.
> 
> Signed-off-by: Byungchul Park <byungchul.park@....com>

Looks good!

Thanks,

-- Steve
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/