From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757623AbbAIOfg (ORCPT ); Fri, 9 Jan 2015 09:35:36 -0500 Received: from smtprelay0151.hostedemail.com ([216.40.44.151]:55995 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1757190AbbAIOfe (ORCPT ); Fri, 9 Jan 2015 09:35:34 -0500 X-Session-Marker: 6E657665747340676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::::::::::::::::::::::::::,RULES_HIT:2:41:355:379:541:599:800:960:966:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1535:1593:1594:1605:1606:1730:1747:1777:1792:1801:2196:2199:2393:2553:2559:2562:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3873:3874:4118:4321:4385:4605:5007:6119:6261:6742:7774:7875:8660:10004:10848:10967:11026:11232:11658:11914:12295:12296:12438:12517:12519:12555:12663:12740:13148:13161:13229:13230:13870:14096:14097:21080,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0 X-HE-Tag: limit49_131ae7ef0c037 X-Filterd-Recvd-Size: 7419 Date: Fri, 9 Jan 2015 09:35:30 -0500 From: Steven Rostedt To: Minchan Kim Cc: Laura Abbott , "Stefan I. Strogin" , linux-mm@kvack.org, linux-kernel@vger.kernel.org, Joonsoo Kim , Andrew Morton , Marek Szyprowski , Michal Nazarewicz , aneesh.kumar@linux.vnet.ibm.com, Laurent Pinchart , Dmitry Safonov , Pintu Kumar , Weijie Yang , SeongJae Park , Hui Zhu , Dyasly Sergey , Vyacheslav Tyrtov , namhyung@kernel.org Subject: Re: [PATCH 0/3] mm: cma: /proc/cmainfo Message-ID: <20150109093530.655c845e@gandalf.local.home> In-Reply-To: <20150109091904.41294966@gandalf.local.home> References: <20141229023639.GC27095@bbox> <54A1B11A.6020307@codeaurora.org> <20141230044726.GA22342@bbox> <20150109091904.41294966@gandalf.local.home> X-Mailer: Claws Mail 3.11.1 (GTK+ 2.24.25; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, 9 Jan 2015 09:19:04 -0500 Steven Rostedt wrote: > task: <...>-2880 > Event: func: __kmalloc() (74) Total: 53254 Avg: 719 Max: 1095 Min:481 I forgot to mention that all times are in nanoseconds (or whatever the trace clock is set at). > | > + ftrace_ops_list_func (0xffffffff810c229e) > 100% (74) time:53254 max:1095 min:481 avg:719 > ftrace_call (0xffffffff81526047) > trace_preempt_on (0xffffffff810d28ff) > preempt_count_sub (0xffffffff81061c62) > __mutex_lock_slowpath (0xffffffff81522807) > __kmalloc (0xffffffff811323f3) > __kmalloc (0xffffffff811323f3) The above may be a bit confusing, as the stack trace included more than it should have (it's variable and hard to get right). ftrace_ops_list_func() did not call kmalloc, but it did call the stack trace and was included. You want to look below to find the interesting data. This is still a new feature, and is using some of the kernel tracing more than it has been in the past. There's still a few eggs that need to be boiled here. > tracing_buffers_splice_read (0xffffffff810ca23e) All the kmallocs for this task was called by tracing_buffers_splice_read() (hmm, I chose to show you the trace-cmd profile on itself. If I had included "-F -c" (follow workload only) or -e sched_switch I would have known which task to look at). > | > + set_next_entity (0xffffffff81067027) > | 66% (49) time:34925 max:1044 min:481 avg:712 > | __switch_to (0xffffffff810016d7) > | trace_hardirqs_on (0xffffffff810d28db) > | _raw_spin_unlock_irq (0xffffffff81523a8e) > | trace_preempt_on (0xffffffff810d28ff) > | preempt_count_sub (0xffffffff81061c62) > | __schedule (0xffffffff815204d3) > | trace_preempt_on (0xffffffff810d28ff) > | buffer_spd_release (0xffffffff810c91fd) > | SyS_splice (0xffffffff8115dccf) > | system_call_fastpath (0xffffffff81523f92) > | > + do_read_fault.isra.74 (0xffffffff8111431d) I'm not sure how much I trust this. I don't have FRAME_POINTERS enabled, so the stack traces may not be as accurate. But you get the idea, and this can show you where the slow paths lie. -- Steve > | 24% (18) time:12654 max:1008 min:481 avg:703 > | | > | + select_task_rq_fair (0xffffffff81067806) > | | 89% (16) time:11234 max:1008 min:481 avg:702 > | | trace_preempt_on (0xffffffff810d28ff) > | | buffer_spd_release (0xffffffff810c91fd) > | | SyS_splice (0xffffffff8115dccf) > | | system_call_fastpath (0xffffffff81523f92) > | | > | + handle_mm_fault (0xffffffff81114df4) > | 11% (2) time:1420 max:879 min:541 avg:710 > | trace_preempt_on (0xffffffff810d28ff) > | buffer_spd_release (0xffffffff810c91fd) > | SyS_splice (0xffffffff8115dccf) > | system_call_fastpath (0xffffffff81523f92) > | > | > | > + update_stats_wait_end (0xffffffff81066c5c) > | 6% (4) time:3153 max:1095 min:635 avg:788 > | set_next_entity (0xffffffff81067027) > | __switch_to (0xffffffff810016d7) > | trace_hardirqs_on (0xffffffff810d28db) > | _raw_spin_unlock_irq (0xffffffff81523a8e) > | trace_preempt_on (0xffffffff810d28ff) > | preempt_count_sub (0xffffffff81061c62) > | __schedule (0xffffffff815204d3) > | trace_preempt_on (0xffffffff810d28ff) > | buffer_spd_release (0xffffffff810c91fd) > | SyS_splice (0xffffffff8115dccf) > | system_call_fastpath (0xffffffff81523f92) > | > + _raw_spin_unlock (0xffffffff81523af5) > | 3% (2) time:1854 max:936 min:918 avg:927 > | do_read_fault.isra.74 (0xffffffff8111431d) > | handle_mm_fault (0xffffffff81114df4) > | buffer_spd_release (0xffffffff810c91fd) > | SyS_splice (0xffffffff8115dccf) > | system_call_fastpath (0xffffffff81523f92) > | > + trace_hardirqs_off (0xffffffff810d2891) > 1% (1) time:668 max:668 min:668 avg:668 > kmem_cache_free (0xffffffff81130e48) > __dequeue_signal (0xffffffff8104c802) > trace_preempt_on (0xffffffff810d28ff) > preempt_count_sub (0xffffffff81061c62) > _raw_spin_unlock_irq (0xffffffff81523a8e) > recalc_sigpending (0xffffffff8104c5d1) > __set_task_blocked (0xffffffff8104cd2e) > trace_preempt_on (0xffffffff810d28ff) > preempt_count_sub (0xffffffff81061c62) > preempt_count_sub (0xffffffff81061c62) > buffer_spd_release (0xffffffff810c91fd) > SyS_splice (0xffffffff8115dccf) > system_call_fastpath (0xffffffff81523f92) >