From patchwork Tue Dec 13 19:48:45 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: subhashj@codeaurora.org X-Patchwork-Id: 9473033 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 3A47E607EE for ; Tue, 13 Dec 2016 19:51:05 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 36FBE28688 for ; Tue, 13 Dec 2016 19:51:05 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 2AE6D2868A; Tue, 13 Dec 2016 19:51:05 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.8 required=2.0 tests=BAYES_00,DKIM_SIGNED, RCVD_IN_DNSWL_HI,T_DKIM_INVALID autolearn=unavailable version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 3EAE828688 for ; Tue, 13 Dec 2016 19:51:04 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934568AbcLMTuH (ORCPT ); Tue, 13 Dec 2016 14:50:07 -0500 Received: from smtp.codeaurora.org ([198.145.29.96]:59410 "EHLO smtp.codeaurora.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753680AbcLMTt1 (ORCPT ); Tue, 13 Dec 2016 14:49:27 -0500 Received: by smtp.codeaurora.org (Postfix, from userid 1000) id B7EDD6159E; Tue, 13 Dec 2016 19:49:26 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=codeaurora.org; s=default; t=1481658566; bh=O0m3XSj6H2f5s4f1Fc4h+9turD4004mdV0oIsuKys0E=; h=From:To:Cc:Subject:Date:From; b=Rh8TqwnH9q64IjJ/JMxB0Vlb27XZVnT4UklJffbSnes9ar2nrHnKtNzv5pCtocSZH JgZfig45TPwiMAVSB1otcAq4+Ah61jAXa36LYMk+FpggEwBXVAdtIc7sa413m2h33+ I6U5rOJnKT4uloytW/DOBuxbJNEFZMBkeswj94xk= Received: from pacamara-linux.qualcomm.com (i-global254.qualcomm.com [199.106.103.254]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-SHA256 (128/128 bits)) (No client certificate requested) (Authenticated sender: subhashj@smtp.codeaurora.org) by smtp.codeaurora.org (Postfix) with ESMTPSA id 82BA2614FD; Tue, 13 Dec 2016 19:49:24 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=codeaurora.org; s=default; t=1481658564; bh=O0m3XSj6H2f5s4f1Fc4h+9turD4004mdV0oIsuKys0E=; h=From:To:Cc:Subject:Date:From; b=Qx0AqWoM+n5x1kN/0HC/cT+2xIWfEuNEnDFKzHQUlEcZllpMZRAF2dItMJs0+CYSc Opv3/mjMUFEjoay09SaH02cLc0LHTLpNzQggla7m1Nwj6OIfE1bF9mH5DiWw4qdA6Q ScPeKrNOfSjkbfnXAOZB6Eoo8vizGj6dWi3y/rLk= DMARC-Filter: OpenDMARC Filter v1.3.1 smtp.codeaurora.org 82BA2614FD Authentication-Results: pdx-caf-mail.web.codeaurora.org; dmarc=none header.from=codeaurora.org Authentication-Results: pdx-caf-mail.web.codeaurora.org; spf=pass smtp.mailfrom=subhashj@codeaurora.org From: Subhash Jadavani To: vinholikatti@gmail.com, jejb@linux.vnet.ibm.com, martin.petersen@oracle.com Cc: linux-scsi@vger.kernel.org, Subhash Jadavani , Steven Rostedt , Ingo Molnar , Sahitya Tummala , Venkat Gopalakrishnan , Lee Susman , linux-kernel@vger.kernel.org (open list) Subject: [PATCH v2 02/12] scsi: ufs: add tracing support Date: Tue, 13 Dec 2016 11:48:45 -0800 Message-Id: <1481658529-31807-1-git-send-email-subhashj@codeaurora.org> X-Mailer: git-send-email 1.9.1 Sender: linux-scsi-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-scsi@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP This change adds the ftrace support for following: 1. UFS initialization time 2. Clock gating states 3. Clock scaling states 4. Power management APIs latency 5. BKOPs enable/disable Usage: echo 1 > /sys/kernel/debug/tracing/events/ufs/enable cat /sys/kernel/debug/tracing/trace_pipe Reviewed-by: Sahitya Tummala Signed-off-by: Subhash Jadavani --- drivers/scsi/ufs/ufshcd.c | 133 ++++++++++++++++++++++++++++++++++++---- include/trace/events/ufs.h | 149 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 270 insertions(+), 12 deletions(-) create mode 100644 include/trace/events/ufs.h diff --git a/drivers/scsi/ufs/ufshcd.c b/drivers/scsi/ufs/ufshcd.c index fe516b2..73c5937 100644 --- a/drivers/scsi/ufs/ufshcd.c +++ b/drivers/scsi/ufs/ufshcd.c @@ -45,6 +45,9 @@ #include "ufs_quirks.h" #include "unipro.h" +#define CREATE_TRACE_POINTS +#include + #define UFSHCD_REQ_SENSE_SIZE 18 #define UFSHCD_ENABLE_INTRS (UTP_TRANSFER_REQ_COMPL |\ @@ -721,6 +724,40 @@ static void ufshcd_resume_clkscaling(struct ufs_hba *hba) devfreq_resume_device(hba->devfreq); } +static const char *ufschd_uic_link_state_to_string( + enum uic_link_state state) +{ + switch (state) { + case UIC_LINK_OFF_STATE: return "UIC_LINK_OFF_STATE"; + case UIC_LINK_ACTIVE_STATE: return "UIC_LINK_ACTIVE_STATE"; + case UIC_LINK_HIBERN8_STATE: return "UIC_LINK_HIBERN8_STATE"; + default: return "UNKNOWN_STATE"; + } +} + +static const char *ufschd_ufs_dev_pwr_mode_to_string( + enum ufs_dev_pwr_mode state) +{ + switch (state) { + case UFS_ACTIVE_PWR_MODE: return "UFS_ACTIVE_PWR_MODE"; + case UFS_SLEEP_PWR_MODE: return "UFS_SLEEP_PWR_MODE"; + case UFS_POWERDOWN_PWR_MODE: return "UFS_POWERDOWN_PWR_MODE"; + default: return "UNKNOWN_STATE"; + } +} + +static const char *ufschd_clk_gating_state_to_string( + enum clk_gating_state state) +{ + switch (state) { + case CLKS_OFF: return "CLKS_OFF"; + case CLKS_ON: return "CLKS_ON"; + case REQ_CLKS_OFF: return "REQ_CLKS_OFF"; + case REQ_CLKS_ON: return "REQ_CLKS_ON"; + default: return "UNKNOWN_STATE"; + } +} + static void ufshcd_ungate_work(struct work_struct *work) { int ret; @@ -801,6 +838,9 @@ int ufshcd_hold(struct ufs_hba *hba, bool async) case REQ_CLKS_OFF: if (cancel_delayed_work(&hba->clk_gating.gate_work)) { hba->clk_gating.state = CLKS_ON; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); break; } /* @@ -811,6 +851,9 @@ int ufshcd_hold(struct ufs_hba *hba, bool async) case CLKS_OFF: scsi_block_requests(hba->host); hba->clk_gating.state = REQ_CLKS_ON; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); schedule_work(&hba->clk_gating.ungate_work); /* * fall through to check if we should wait for this @@ -855,6 +898,9 @@ static void ufshcd_gate_work(struct work_struct *work) if (hba->clk_gating.is_suspended || (hba->clk_gating.state == REQ_CLKS_ON)) { hba->clk_gating.state = CLKS_ON; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); goto rel_lock; } @@ -870,6 +916,9 @@ static void ufshcd_gate_work(struct work_struct *work) if (ufshcd_can_hibern8_during_gating(hba)) { if (ufshcd_uic_hibern8_enter(hba)) { hba->clk_gating.state = CLKS_ON; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); goto out; } ufshcd_set_link_hibern8(hba); @@ -893,9 +942,12 @@ static void ufshcd_gate_work(struct work_struct *work) * new requests arriving before the current cancel work is done. */ spin_lock_irqsave(hba->host->host_lock, flags); - if (hba->clk_gating.state == REQ_CLKS_OFF) + if (hba->clk_gating.state == REQ_CLKS_OFF) { hba->clk_gating.state = CLKS_OFF; - + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); + } rel_lock: spin_unlock_irqrestore(hba->host->host_lock, flags); out: @@ -918,6 +970,9 @@ static void __ufshcd_release(struct ufs_hba *hba) return; hba->clk_gating.state = REQ_CLKS_OFF; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); schedule_delayed_work(&hba->clk_gating.gate_work, msecs_to_jiffies(hba->clk_gating.delay_ms)); } @@ -3932,6 +3987,7 @@ static int ufshcd_enable_auto_bkops(struct ufs_hba *hba) } hba->auto_bkops_enabled = true; + trace_ufshcd_auto_bkops_state(dev_name(hba->dev), "Enabled"); /* No need of URGENT_BKOPS exception from the device */ err = ufshcd_disable_ee(hba, MASK_EE_URGENT_BKOPS); @@ -3982,6 +4038,7 @@ static int ufshcd_disable_auto_bkops(struct ufs_hba *hba) } hba->auto_bkops_enabled = false; + trace_ufshcd_auto_bkops_state(dev_name(hba->dev), "Disabled"); out: return err; } @@ -5377,6 +5434,7 @@ static void ufshcd_tune_unipro_params(struct ufs_hba *hba) static int ufshcd_probe_hba(struct ufs_hba *hba) { int ret; + ktime_t start = ktime_get(); ret = ufshcd_link_startup(hba); if (ret) @@ -5468,6 +5526,10 @@ static int ufshcd_probe_hba(struct ufs_hba *hba) ufshcd_hba_exit(hba); } + trace_ufshcd_init(dev_name(hba->dev), ret, + ktime_to_us(ktime_sub(ktime_get(), start)), + ufschd_uic_link_state_to_string(hba->uic_link_state), + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode)); return ret; } @@ -5817,11 +5879,15 @@ static int __ufshcd_setup_clocks(struct ufs_hba *hba, bool on, if (!IS_ERR_OR_NULL(clki->clk) && clki->enabled) clk_disable_unprepare(clki->clk); } - } else if (on) { + } else if (!ret && on) { spin_lock_irqsave(hba->host->host_lock, flags); hba->clk_gating.state = CLKS_ON; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string( + hba->clk_gating.state)); spin_unlock_irqrestore(hba->host->host_lock, flags); } + return ret; } @@ -6304,6 +6370,8 @@ static int ufshcd_suspend(struct ufs_hba *hba, enum ufs_pm_op pm_op) __ufshcd_setup_clocks(hba, false, true); hba->clk_gating.state = CLKS_OFF; + trace_ufshcd_clk_gating(dev_name(hba->dev), + ufschd_clk_gating_state_to_string(hba->clk_gating.state)); /* * Disable the host irq as host controller as there won't be any * host controller transaction expected till resume. @@ -6436,6 +6504,7 @@ static int ufshcd_resume(struct ufs_hba *hba, enum ufs_pm_op pm_op) int ufshcd_system_suspend(struct ufs_hba *hba) { int ret = 0; + ktime_t start = ktime_get(); if (!hba || !hba->is_powered) return 0; @@ -6462,6 +6531,10 @@ int ufshcd_system_suspend(struct ufs_hba *hba) ret = ufshcd_suspend(hba, UFS_SYSTEM_PM); out: + trace_ufshcd_system_suspend(dev_name(hba->dev), ret, + ktime_to_us(ktime_sub(ktime_get(), start)), + ufschd_uic_link_state_to_string(hba->uic_link_state), + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode)); if (!ret) hba->is_sys_suspended = true; return ret; @@ -6477,6 +6550,9 @@ int ufshcd_system_suspend(struct ufs_hba *hba) int ufshcd_system_resume(struct ufs_hba *hba) { + int ret = 0; + ktime_t start = ktime_get(); + if (!hba) return -EINVAL; @@ -6485,9 +6561,15 @@ int ufshcd_system_resume(struct ufs_hba *hba) * Let the runtime resume take care of resuming * if runtime suspended. */ - return 0; - - return ufshcd_resume(hba, UFS_SYSTEM_PM); + goto out; + else + ret = ufshcd_resume(hba, UFS_SYSTEM_PM); +out: + trace_ufshcd_system_resume(dev_name(hba->dev), ret, + ktime_to_us(ktime_sub(ktime_get(), start)), + ufschd_uic_link_state_to_string(hba->uic_link_state), + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode)); + return ret; } EXPORT_SYMBOL(ufshcd_system_resume); @@ -6501,13 +6583,22 @@ int ufshcd_system_resume(struct ufs_hba *hba) */ int ufshcd_runtime_suspend(struct ufs_hba *hba) { + int ret = 0; + ktime_t start = ktime_get(); + if (!hba) return -EINVAL; if (!hba->is_powered) - return 0; - - return ufshcd_suspend(hba, UFS_RUNTIME_PM); + goto out; + else + ret = ufshcd_suspend(hba, UFS_RUNTIME_PM); +out: + trace_ufshcd_runtime_suspend(dev_name(hba->dev), ret, + ktime_to_us(ktime_sub(ktime_get(), start)), + ufschd_uic_link_state_to_string(hba->uic_link_state), + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode)); + return ret; } EXPORT_SYMBOL(ufshcd_runtime_suspend); @@ -6534,13 +6625,22 @@ int ufshcd_runtime_suspend(struct ufs_hba *hba) */ int ufshcd_runtime_resume(struct ufs_hba *hba) { + int ret = 0; + ktime_t start = ktime_get(); + if (!hba) return -EINVAL; if (!hba->is_powered) - return 0; - - return ufshcd_resume(hba, UFS_RUNTIME_PM); + goto out; + else + ret = ufshcd_resume(hba, UFS_RUNTIME_PM); +out: + trace_ufshcd_runtime_resume(dev_name(hba->dev), ret, + ktime_to_us(ktime_sub(ktime_get(), start)), + ufschd_uic_link_state_to_string(hba->uic_link_state), + ufschd_ufs_dev_pwr_mode_to_string(hba->curr_dev_pwr_mode)); + return ret; } EXPORT_SYMBOL(ufshcd_runtime_resume); @@ -6684,6 +6784,11 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) clki->max_freq, ret); break; } + trace_ufshcd_clk_scaling(dev_name(hba->dev), + "scaled up", clki->name, + clki->curr_freq, + clki->max_freq); + clki->curr_freq = clki->max_freq; } else if (!scale_up && clki->min_freq) { @@ -6696,6 +6801,10 @@ static int ufshcd_scale_clks(struct ufs_hba *hba, bool scale_up) clki->min_freq, ret); break; } + trace_ufshcd_clk_scaling(dev_name(hba->dev), + "scaled down", clki->name, + clki->curr_freq, + clki->min_freq); clki->curr_freq = clki->min_freq; } } diff --git a/include/trace/events/ufs.h b/include/trace/events/ufs.h new file mode 100644 index 0000000..7b3d9e1 --- /dev/null +++ b/include/trace/events/ufs.h @@ -0,0 +1,149 @@ +/* + * Copyright (c) 2013-2014, The Linux Foundation. All rights reserved. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License version 2 and + * only version 2 as published by the Free Software Foundation. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + */ + +#undef TRACE_SYSTEM +#define TRACE_SYSTEM ufs + +#if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_UFS_H + +#include + +TRACE_EVENT(ufshcd_clk_gating, + + TP_PROTO(const char *dev_name, const char *state), + + TP_ARGS(dev_name, state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(state, state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(state, state); + ), + + TP_printk("%s: gating state changed to %s", + __get_str(dev_name), __get_str(state)) +); + +TRACE_EVENT(ufshcd_clk_scaling, + + TP_PROTO(const char *dev_name, const char *state, const char *clk, + u32 prev_state, u32 curr_state), + + TP_ARGS(dev_name, state, clk, prev_state, curr_state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(state, state) + __string(clk, clk) + __field(u32, prev_state) + __field(u32, curr_state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(state, state); + __assign_str(clk, clk); + __entry->prev_state = prev_state; + __entry->curr_state = curr_state; + ), + + TP_printk("%s: %s %s from %u to %u Hz", + __get_str(dev_name), __get_str(state), __get_str(clk), + __entry->prev_state, __entry->curr_state) +); + +TRACE_EVENT(ufshcd_auto_bkops_state, + + TP_PROTO(const char *dev_name, const char *state), + + TP_ARGS(dev_name, state), + + TP_STRUCT__entry( + __string(dev_name, dev_name) + __string(state, state) + ), + + TP_fast_assign( + __assign_str(dev_name, dev_name); + __assign_str(state, state); + ), + + TP_printk("%s: auto bkops - %s", + __get_str(dev_name), __get_str(state)) +); + +DECLARE_EVENT_CLASS(ufshcd_template, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + + TP_ARGS(dev_name, err, usecs, dev_state, link_state), + + TP_STRUCT__entry( + __field(s64, usecs) + __field(int, err) + __string(dev_name, dev_name) + __string(dev_state, dev_state) + __string(link_state, link_state) + ), + + TP_fast_assign( + __entry->usecs = usecs; + __entry->err = err; + __assign_str(dev_name, dev_name); + __assign_str(dev_state, dev_state); + __assign_str(link_state, link_state); + ), + + TP_printk( + "%s: took %lld usecs, dev_state: %s, link_state: %s, err %d", + __get_str(dev_name), + __entry->usecs, + __get_str(dev_state), + __get_str(link_state), + __entry->err + ) +); + +DEFINE_EVENT(ufshcd_template, ufshcd_system_suspend, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_system_resume, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_suspend, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_runtime_resume, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); + +DEFINE_EVENT(ufshcd_template, ufshcd_init, + TP_PROTO(const char *dev_name, int err, s64 usecs, + const char *dev_state, const char *link_state), + TP_ARGS(dev_name, err, usecs, dev_state, link_state)); +#endif /* if !defined(_TRACE_UFS_H) || defined(TRACE_HEADER_MULTI_READ) */ + +/* This part must be outside protection */ +#include