From patchwork Tue Mar 7 13:39:20 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Mimi Zohar X-Patchwork-Id: 9609631 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 9B2CA6016C for ; Tue, 7 Mar 2017 18:36:25 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 8D56D284FA for ; Tue, 7 Mar 2017 18:36:25 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 817B528504; Tue, 7 Mar 2017 18:36:25 +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.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI 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 D21D028502 for ; Tue, 7 Mar 2017 18:36:24 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932683AbdCGSgW (ORCPT ); Tue, 7 Mar 2017 13:36:22 -0500 Received: from mx0a-001b2d01.pphosted.com ([148.163.156.1]:43283 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932696AbdCGSgT (ORCPT ); Tue, 7 Mar 2017 13:36:19 -0500 Received: from pps.filterd (m0098396.ppops.net [127.0.0.1]) by mx0a-001b2d01.pphosted.com (8.16.0.20/8.16.0.20) with SMTP id v27DXiX7063930 for ; Tue, 7 Mar 2017 08:40:18 -0500 Received: from e23smtp09.au.ibm.com (e23smtp09.au.ibm.com [202.81.31.142]) by mx0a-001b2d01.pphosted.com with ESMTP id 291wqcgpkp-1 (version=TLSv1.2 cipher=AES256-SHA bits=256 verify=NOT) for ; Tue, 07 Mar 2017 08:40:18 -0500 Received: from localhost by e23smtp09.au.ibm.com with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted for from ; Tue, 7 Mar 2017 23:40:15 +1000 Received: from d23dlp03.au.ibm.com (202.81.31.214) by e23smtp09.au.ibm.com (202.81.31.206) with IBM ESMTP SMTP Gateway: Authorized Use Only! Violators will be prosecuted; Tue, 7 Mar 2017 23:40:13 +1000 Received: from d23relay06.au.ibm.com (d23relay06.au.ibm.com [9.185.63.219]) by d23dlp03.au.ibm.com (Postfix) with ESMTP id 755B63578053; Wed, 8 Mar 2017 00:40:12 +1100 (EST) Received: from d23av04.au.ibm.com (d23av04.au.ibm.com [9.190.235.139]) by d23relay06.au.ibm.com (8.14.9/8.14.9/NCO v10.0) with ESMTP id v27De4IQ53018650; Wed, 8 Mar 2017 00:40:12 +1100 Received: from d23av04.au.ibm.com (localhost [127.0.0.1]) by d23av04.au.ibm.com (8.14.4/8.14.4/NCO v10.0 AVout) with ESMTP id v27DddcJ024762; Wed, 8 Mar 2017 00:39:40 +1100 Received: from localhost.localdomain ([9.80.107.179]) by d23av04.au.ibm.com (8.14.4/8.14.4/NCO v10.0 AVin) with ESMTP id v27DdaDR024452; Wed, 8 Mar 2017 00:39:37 +1100 Subject: Re: [RFC PATCH] tpm: msleep() delays - replace with usleep_range() in i2c nuvoton driver From: Mimi Zohar To: Jarkko Sakkinen , Thomas Gleixner Cc: tpmdd-devel , Thomas@intel.com, Dan Morav , linux-fsdevel , linux-security-module , linux-ima-devel Date: Tue, 07 Mar 2017 08:39:20 -0500 In-Reply-To: <20170302083347.q33wiwsdcwbxyrp6@intel.com> References: <1487893578.3193.155.camel@linux.vnet.ibm.com> <20170224170100.prwbcsffxdqjudc2@intel.com> <1487957342.3193.200.camel@linux.vnet.ibm.com> <20170302083347.q33wiwsdcwbxyrp6@intel.com> X-Mailer: Evolution 3.12.11 (3.12.11-1.fc21) Mime-Version: 1.0 X-TM-AS-MML: disable X-Content-Scanned: Fidelis XPS MAILER x-cbid: 17030713-0052-0000-0000-0000021FC777 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17030713-0053-0000-0000-000007EB88AD Message-Id: <1488893960.3216.45.camel@linux.vnet.ibm.com> X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:, , definitions=2017-03-07_09:, , signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 spamscore=0 suspectscore=0 malwarescore=0 phishscore=0 adultscore=0 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1702020001 definitions=main-1703070114 Sender: linux-fsdevel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-fsdevel@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP On Thu, 2017-03-02 at 10:33 +0200, Jarkko Sakkinen wrote: > On Fri, Feb 24, 2017 at 12:29:02PM -0500, Mimi Zohar wrote: > > On Fri, 2017-02-24 at 19:01 +0200, Jarkko Sakkinen wrote: > > > On Thu, Feb 23, 2017 at 06:46:18PM -0500, Mimi Zohar wrote: > > > > Commit 500462a9de65 "timers: Switch to a non-cascading wheel" replaced > > > > the 'classic' timer wheel, which aimed for near 'exact' expiry of the > > > > timers. Their analysis was that the vast majority of timeout timers > > > > are used as safeguards, not as real timers, and are cancelled or > > > > rearmed before expiration. The only exception noted to this were > > > > networking timers with a small expiry time. > > > > > > > > Not included in the analysis was the TPM polling timer, which resulted > > > > in a longer normal delay and, every so often, a very long delay. The > > > > non-cascading wheel delay is based on CONFIG_HZ. For a description of > > > > the different rings and their delays, refer to the comments in > > > > kernel/time/timer.c. > > > > > > > > Below are the delays given for rings 0 - 2, which explains the longer > > > > "normal" delays and the very, long delays as seen on systems with > > > > CONFIG_HZ 250. > > > > > > > > * HZ 1000 steps > > > > * Level Offset Granularity Range > > > > * 0 0 1 ms 0 ms - 63 ms > > > > * 1 64 8 ms 64 ms - 511 ms > > > > * 2 128 64 ms 512 ms - 4095 ms (512ms - ~4s) > > > > > > > > * HZ 250 > > > > * Level Offset Granularity Range > > > > * 0 0 4 ms 0 ms - 255 ms > > > > * 1 64 32 ms 256 ms - 2047 ms (256ms - ~2s) > > > > * 2 128 256 ms 2048 ms - 16383 ms (~2s - ~16s) > > > > > > > > Below is a comparison of extending the TPM with 1000 measurements, > > > > using msleep() vs. usleep_delay() when configured for 1000 hz vs. 250 > > > > hz, before and after commit 500462a9de65. > > > > > > > > linux-4.7 | msleep() usleep_range() > > > > 1000 hz: 0m44.628s | 1m34.497s 29.243s > > > > 250 hz: 1m28.510s | 4m49.269s 32.386s > > > > > > > > linux-4.7 | min-max (msleep) min-max (usleep_range) > > > > 1000 hz: 0:017 - 2:760s | 0:015 - 3:967s 0:014 - 0:418s > > > > 250 hz: 0:028 - 1:954s | 0:040 - 4:096s 0:016 - 0:816s > > > > > > > > This patch replaces the msleep() with usleep_range() calls in the > > > > i2c nuvoton driver with a consistent max range value. > > > > > > > > Signed-of-by: Mimi Zohar > > > > Reviewed-by: Nayna Jain > > > > > > So why doesn't it go to level 0 with msleep()? I quickly skimmed > > > through __mod_timer() and for me it looked like that level 0 would be > > > calculated (when it is eventually called starting from msleep()). > > > What did I miss? > > > > I've just added some printk's in kernel/time/timer.c. It looks like it > > is level 0. The delay seems to be caused by schedule() in > > schedule_timeout(). > > > > setup_timer_on_stack(&timer, process_timeout, (unsigned > > long)current); > > __mod_timer(&timer, expire, false, false); > > schedule(); <=== > > del_singleshot_timer_sync(&timer); > > > > /* Remove the timer from the object tracker */ > > destroy_timer_on_stack(&timer); > > > > > > printks output: > > 124.901002] calc_wheel_index: level 0 timer: c000003fab32b150 expires > > 4294923520 new expires 4294923520 now 4294923518 > > [ 124.901003] __mod_timer: exit timer c000003fab32b1a0 now 4294923518 > > > > < call to schedule() > > > > > [ 128.607463] schedule_timeout: before destroy timer: c000003fab32b150 > > expires 4294923520 now 4294924439 <=== notice that the "now" time is > > way beyond the expires time. > > > > Mimi > > Hey, I totally forgot this patch! Sorry. > > Reviewed-by: Jarkko Sakkinen Thanks, Jarkko! From looking at the code and adding some printks, the TPM extends should have been in level 0. We were left wondering why msleep() was performing so poorly. Unfortunately, we haven't gotten very far. Initially we thought it might be in "is_idle", but can't even confirm that. Sprinkling "printks" isn't very useful as it changes the timing. Even adding "1" like in the change below improved the performance a lot as shown in the table below. Thomas, any suggestions? Even with this improvement, it doesn't come near to that of using usleep_range(). I'm not sure what all this means for the rest of the msleep()s, but at this point, I do appreciate your upstreaming this patch. I hard coded the usleep_range to 300. Any suggestions on what the max usleep_range() should be? 4.10.1 | 4.10.1+ with "+ 1" change --------------------------------------------------------------- real 3m33.510s 1m29.628s user 0m1.273s 0m1.296s sys 0m7.518s 0m5.363s diff --git a/kernel/time/timer.c b/kernel/time/timer.c index d7f6984ce682..9d3c2ab7011f 100644 --- a/kernel/time/timer.c +++ b/kernel/time/timer.c @@ -1504,7 +1504,7 @@ static u64 cmp_next_hrtimer_event(u64 basem, u64 expires) u64 get_next_timer_interrupt(unsigned long basej, u64 basem) { struct timer_base *base = this_cpu_ptr(&timer_bases[BASE_STD]); - u64 expires = KTIME_MAX; + u64 expire_time, expires = KTIME_MAX; unsigned long nextevt; bool is_max_delta; @@ -1545,7 +1545,8 @@ u64 get_next_timer_interrupt(unsigned long basej, u64 basem) } spin_unlock(&base->lock); - return cmp_next_hrtimer_event(basem, expires); + expire_time = cmp_next_hrtimer_event(basem, expires); + return (is_max_delta) ? expire_time : expire_time + 1; } Mimi