| Message ID | 20231207111223.234170-1-pvorel@suse.cz |
|---|---|
| State | Changes Requested |
| Headers | show |
| Series | [1/1] fsx-linux: Reduce log output | expand |
> Log output is very verbose. Given how many times the test tries it's a > significant time spent for printing output. This change also helps to > run on slower SUT without need to set LTP_TIMEOUT_MUL environment > variable. IMHO output should have been only on error (test run 10000x or 100000x or even 500000x, that's a lot for a regular output). Also logs get huge due logging. Kind regards, Petr
Hi! > IMHO output should have been only on error (test run 10000x or 100000x or even > 500000x, that's a lot for a regular output). Also logs get huge due logging. Generally tests should print a few lines by default, having too much output can easily flood serial console or any other slow output and slow down thigns considerably. Verbose output may be useful for debugging though. Maybe we need TVERB flag and default test library '-v' parameter that would enable such messages.
> Hi! > > IMHO output should have been only on error (test run 10000x or 100000x or even > > 500000x, that's a lot for a regular output). Also logs get huge due logging. > Generally tests should print a few lines by default, having too much > output can easily flood serial console or any other slow output and slow > down thigns considerably. > Verbose output may be useful for debugging though. Maybe we need > TVERB flag and default test library '-v' parameter that would enable > such messages. Good point. Unless anybody objects, I'll send v2 with this and Cc others. Kind regards, Petr
Hi, more than TVERB, it would be nice to add a "verbose_flag". Something like: tst_res(TINFO, "my message %s", my_param, verbose_flag) And then with a -v we filter out messages which are verbose or not. In this way we don't add T-flags and we can handle any kind of messages in verbose mode. Andrea On 12/7/23 12:22, Cyril Hrubis wrote: > Hi! >> IMHO output should have been only on error (test run 10000x or 100000x or even >> 500000x, that's a lot for a regular output). Also logs get huge due logging. > Generally tests should print a few lines by default, having too much > output can easily flood serial console or any other slow output and slow > down thigns considerably. > > Verbose output may be useful for debugging though. Maybe we need > TVERB flag and default test library '-v' parameter that would enable > such messages. >
Hi! > more than TVERB, it would be nice to add a "verbose_flag". Something like: > > tst_res(TINFO, "my message %s", my_param, verbose_flag) That's technically impossible, because the printf() like messages have variable number of parameters. Also it's really hard to extend the API at this point without really breaking it. We would have to also rewrite a few thousands of test if we introduce such change, which may be possible with coccinelle, but I would rather avoid such hassle. > And then with a -v we filter out messages which are verbose or not. > In this way we don't add T-flags and we can handle any kind of messages > in verbose mode. If you are worried about the output, we can easily produce TINFO messages for the TVERB flag too. Or possibly name the flags as TINFO with a debug level appended e.g. we can add TINFO0, TINFO1 and TINFO2 and define TINFO to TNFO0 for backwards compatibility.
On 12/7/23 13:25, Cyril Hrubis wrote: > Hi! >> more than TVERB, it would be nice to add a "verbose_flag". Something like: >> >> tst_res(TINFO, "my message %s", my_param, verbose_flag) > That's technically impossible, because the printf() like messages have > variable number of parameters. > > Also it's really hard to extend the API at this point without really > breaking it. We would have to also rewrite a few thousands of test if we > introduce such change, which may be possible with coccinelle, but I > would rather avoid such hassle. > >> And then with a -v we filter out messages which are verbose or not. >> In this way we don't add T-flags and we can handle any kind of messages >> in verbose mode. > If you are worried about the output, we can easily produce TINFO > messages for the TVERB flag too. > > Or possibly name the flags as TINFO with a debug level appended e.g. we > can add TINFO0, TINFO1 and TINFO2 and define TINFO to TNFO0 for > backwards compatibility. > What about mixing TVERB flag with the others ? Something like "TINFO | TVERB" Andrea
Hi! > What about mixing TVERB flag with the others ? Something like "TINFO | > TVERB" That's too much typing to be honest. Maybe TVINFO?
On 12/7/23 13:32, Cyril Hrubis wrote: > Hi! >> What about mixing TVERB flag with the others ? Something like "TINFO | >> TVERB" > That's too much typing to be honest. Maybe TVINFO? > "TINFO | TVERB" makes somehow sense, since we can have it for other flags as well. And we have the same for TERRNO Andrea
Hi! > >> What about mixing TVERB flag with the others ? Something like "TINFO | > >> TVERB" > > That's too much typing to be honest. Maybe TVINFO? > > > "TINFO | TVERB" makes somehow sense, since we can have it for other > flags as well. > And we have the same for TERRNO The difference is that TERRNO is applicable to all other types such as TPASS, TFAIL, TBROK, TWARN. This does not make sense for TVERB, you probably do not want to hide passed messages and you certainly do not want to hide falures, bereakages and warnings...
On 12/7/23 13:39, Cyril Hrubis wrote: > Hi! >>>> What about mixing TVERB flag with the others ? Something like "TINFO | >>>> TVERB" >>> That's too much typing to be honest. Maybe TVINFO? >>> >> "TINFO | TVERB" makes somehow sense, since we can have it for other >> flags as well. >> And we have the same for TERRNO > The difference is that TERRNO is applicable to all other types such as > TPASS, TFAIL, TBROK, TWARN. This does not make sense for TVERB, you > probably do not want to hide passed messages and you certainly do not > want to hide falures, bereakages and warnings... > I was thinking more about TWARN and TINFO. Andrea
> Hi! > > more than TVERB, it would be nice to add a "verbose_flag". Something like: @Cyril: Or maybe TDEBUG to be more obvious? I'll enable them on "-v" or on LTP_VERBOSE=1 parameter. Also, do we want to add it also to the shell API? -v parameter is used nfs_lib.sh, I wonder into which to rename (-V is used for LTP version in C API, I guess I should have add it to shell API as well). > > tst_res(TINFO, "my message %s", my_param, verbose_flag) > That's technically impossible, because the printf() like messages have > variable number of parameters. +1 > Also it's really hard to extend the API at this point without really > breaking it. We would have to also rewrite a few thousands of test if we > introduce such change, which may be possible with coccinelle, but I > would rather avoid such hassle. +1 @Andrea, I also don't see a big problem with having TVERB flag. All of them are somehow informative, although most of them also quit. Kind regards, Petr > > And then with a -v we filter out messages which are verbose or not. > > In this way we don't add T-flags and we can handle any kind of messages > > in verbose mode. > If you are worried about the output, we can easily produce TINFO > messages for the TVERB flag too. > Or possibly name the flags as TINFO with a debug level appended e.g. we > can add TINFO0, TINFO1 and TINFO2 and define TINFO to TNFO0 for > backwards compatibility.
Hi! > > The difference is that TERRNO is applicable to all other types such as > > TPASS, TFAIL, TBROK, TWARN. This does not make sense for TVERB, you > > probably do not want to hide passed messages and you certainly do not > > want to hide falures, bereakages and warnings... > > > I was thinking more about TWARN and TINFO. I'm not sure that we would want to add lesser warnings, i.e. TWARN | TVERB. We use TWARN mostly in cases where cleanup failed in test cleanup() and possibly the OS is in an inconsistent state. Also TWARN is used in places where we would have used TBROK but the test is somehow able to continue at least partially. I do not think that I have a use for TWARN | TVERB.
On 12/7/23 13:44, Cyril Hrubis wrote: > Hi! >>> The difference is that TERRNO is applicable to all other types such as >>> TPASS, TFAIL, TBROK, TWARN. This does not make sense for TVERB, you >>> probably do not want to hide passed messages and you certainly do not >>> want to hide falures, bereakages and warnings... >>> >> I was thinking more about TWARN and TINFO. > I'm not sure that we would want to add lesser warnings, i.e. TWARN | > TVERB. We use TWARN mostly in cases where cleanup failed in test > cleanup() and possibly the OS is in an inconsistent state. Also TWARN is > used in places where we would have used TBROK but the test is somehow > able to continue at least partially. I do not think that I have a use > for TWARN | TVERB. > Ok, so TDEBUG or TVERBOSE are both nice for me. Andrea
Hi!
> Ok, so TDEBUG or TVERBOSE are both nice for me.
TDEBUG sounds good, if we wanted to adhere to the four letter lenght as
we do with the rest it would probably be TDBUG, but either one is fine I
guess.
diff --git a/testcases/kernel/fs/fsx-linux/fsx-linux.c b/testcases/kernel/fs/fsx-linux/fsx-linux.c index 112c21f85..375ef4a1a 100644 --- a/testcases/kernel/fs/fsx-linux/fsx-linux.c +++ b/testcases/kernel/fs/fsx-linux/fsx-linux.c @@ -98,7 +98,6 @@ static void update_file_size(struct file_pos_t const *pos) { if (pos->offset + pos->size > file_size) { file_size = pos->offset + pos->size; - tst_res(TINFO, "File size changed: %llu", file_size); } } @@ -134,12 +133,6 @@ static int op_read(void) struct file_pos_t pos; op_file_position(file_size, op_read_align, &pos); - - tst_res(TINFO, - "Reading at offset=%llu, size=%llu", - pos.offset, - pos.size); - memset(temp_buff, 0, file_max_size); SAFE_LSEEK(file_desc, (off_t)pos.offset, SEEK_SET); @@ -176,11 +169,6 @@ static int op_write(void) temp_buff[i] = data; } - tst_res(TINFO, - "Writing at offset=%llu, size=%llu", - pos.offset, - pos.size); - SAFE_LSEEK(file_desc, (off_t)pos.offset, SEEK_SET); SAFE_WRITE(SAFE_WRITE_ALL, file_desc, temp_buff, pos.size); @@ -194,11 +182,7 @@ static int op_truncate(void) struct file_pos_t pos; op_file_position(file_max_size, op_trunc_align, &pos); - file_size = pos.offset + pos.size; - - tst_res(TINFO, "Truncating to %llu", file_size); - SAFE_FTRUNCATE(file_desc, file_size); memset(file_buff + file_size, 0, file_max_size - file_size); @@ -218,11 +202,6 @@ static int op_map_read(void) op_file_position(file_size, op_read_align, &pos); op_align_pages(&pos); - tst_res(TINFO, - "Map reading at offset=%llu, size=%llu", - pos.offset, - pos.size); - addr = SAFE_MMAP( 0, pos.size, PROT_READ, @@ -261,11 +240,6 @@ static int op_map_write(void) if (file_size < pos.offset + pos.size) SAFE_FTRUNCATE(file_desc, pos.offset + pos.size); - tst_res(TINFO, - "Map writing at offset=%llu, size=%llu", - pos.offset, - pos.size); - for (long long i = 0; i < pos.size; i++) file_buff[pos.offset + i] = random() % 10 + 'l'; @@ -277,10 +251,13 @@ static int op_map_write(void) (off_t)pos.offset); memcpy(addr, file_buff + pos.offset, pos.size); - msync(addr, pos.size, MS_SYNC); - SAFE_MUNMAP(addr, pos.size); + if (msync(addr, pos.size, MS_SYNC) != 0) { + tst_res(TWARN, "Map writing at offset=%llu, size=%llu failed", + pos.offset, pos.size); + } + SAFE_MUNMAP(addr, pos.size); update_file_size(&pos); return 1;
Log output is very verbose. Given how many times the test tries it's a significant time spent for printing output. This change also helps to run on slower SUT without need to set LTP_TIMEOUT_MUL environment variable. Signed-off-by: Petr Vorel <pvorel@suse.cz> --- testcases/kernel/fs/fsx-linux/fsx-linux.c | 33 ++++------------------- 1 file changed, 5 insertions(+), 28 deletions(-)