netdev - Re: [RFC iproute2-next] devlink: display elapsed time during flash update

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 linux-cve-announce PHC
Open Source and information security mailing list archives

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

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

Message-ID: <b4f664d9-301c-1157-0049-50dbea856dda@intel.com>
Date:   Tue, 29 Sep 2020 10:56:23 -0700
From:   Jacob Keller <jacob.e.keller@...el.com>
To:     Jakub Kicinski <kubakici@...pl>
Cc:     netdev@...r.kernel.org, snelson@...sando.io
Subject: Re: [RFC iproute2-next] devlink: display elapsed time during flash
 update



On 9/29/2020 10:18 AM, Jakub Kicinski wrote:
> On Mon, 28 Sep 2020 16:49:45 -0700 Jacob Keller wrote:
>> For some devices, updating the flash can take significant time during
>> operations where no status can meaningfully be reported. This can be
>> somewhat confusing to a user who sees devlink appear to hang on the
>> terminal waiting for the device to update.
>>
>> Provide a ticking counter of the time elapsed since the previous status
>> message in order to make it clear that the program is not simply stuck.
>>
>> Do not display this message unless a few seconds have passed since the
>> last status update. Additionally, if the previous status notification
>> included a timeout, display this as part of the message. If we do not
>> receive an error or a new status without that time out, replace it with
>> the text "timeout reached".
>>
>> Signed-off-by: Jacob Keller <jacob.e.keller@...el.com>
>> ---
>> Sending this as an RFC because I doubt this is the best implementation. For
>> one, I get a weird display issue where the cursor doesn't always end up on
>> the end of line in my shell.. The % display works properly, so I'm not sure
>> what's wrong here.
>>
>> Second, even though select should be timing out every 1/10th of a second for
>> screen updates, I don't seem to get that behavior in my test. It takes about
>> 8 to 10 seconds for the first elapsed time message to be displayed, and it
>> updates really slowly. Is select just not that precise? I even tried using a
>> timeout of zero, but this means we refresh way too often and it looks bad. I
>> am not sure what is wrong here...
> 
> Strange. Did you strace it? Perhaps it's some form of output buffering?
> 

Haven't yet, just noticed the weird output behavior and timing
inconsistency.

>> diff --git a/devlink/devlink.c b/devlink/devlink.c
>> index 0374175eda3d..7fb4b5ef1ebe 100644
>> --- a/devlink/devlink.c
>> +++ b/devlink/devlink.c
>> @@ -33,6 +33,7 @@
>>  #include <sys/select.h>
>>  #include <sys/socket.h>
>>  #include <sys/types.h>
>> +#include <sys/time.h>
>>  #include <rt_names.h>
>>  
>>  #include "version.h"
>> @@ -3066,6 +3067,9 @@ static int cmd_dev_info(struct dl *dl)
>>  
>>  struct cmd_dev_flash_status_ctx {
>>  	struct dl *dl;
>> +	struct timeval last_status_msg;
>> +	char timeout_msg[128];
> 
> Really you just need the length (as returned by snprintf), right?

Hmm, yea probably don't need the full message.
> 
>> +	uint64_t timeout;
>>  	char *last_msg;
>>  	char *last_component;
>>  	uint8_t not_first:1,
>> @@ -3083,6 +3087,14 @@ static int nullstrcmp(const char *str1, const char *str2)
>>  	return str1 ? 1 : -1;
>>  }
>>  
>> +static void cmd_dev_flash_clear_elapsed_time(struct cmd_dev_flash_status_ctx *ctx)
>> +{
>> +	int i;
>> +
>> +	for (i = 0; i < strlen(ctx->timeout_msg); i++)
>> +		pr_out_tty("\b");
> 
> I wonder if it's not easier to \r, I guess the existing code likes \b
> so be it.
> 

If we '\r', we'd have to re-write the whole line, right? Hmm.

I'm also thinking that perhaps part of the display issue is that these
"\b" outputs aren't being sent as one unit so some sort of buffering
results in the inconsistent display. Note, the text does fully display
properly, it just doesn't seem to update the cursor location correctly,
resulting in the cursor position bouncing around rapidly and being very
distracting.

>> +}
>> +
>>  static int cmd_dev_flash_status_cb(const struct nlmsghdr *nlh, void *data)
>>  {
>>  	struct cmd_dev_flash_status_ctx *ctx = data;
> 
>> +static void cmd_dev_flash_time_elapsed(struct cmd_dev_flash_status_ctx *ctx)
>> +{
>> +	struct timeval now, res;
>> +
>> +	gettimeofday(&now, NULL);
>> +	timersub(&now, &ctx->last_status_msg, &res);
>> +
>> +	/* Don't start displaying a timeout message until we've elapsed a few
>> +	 * seconds...
>> +	 */
>> +	if (res.tv_sec > 3) {
>> +		uint elapsed_m, elapsed_s;
> 
> This may be the first uint use in iproute2..

>> +		/* clear the last elapsed time message, if we have one */
>> +		cmd_dev_flash_clear_elapsed_time(ctx);
>> +
>> +		elapsed_m = res.tv_sec / 60;
>> +		elapsed_s = res.tv_sec % 60;