[committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Tom de Vries]

Hi,

Once in a while, I run into this timeout:
...
FAIL: gdb.mi/mi-sym-info.exp: List all variables from debug information \
  only (timeout)
...

I can make the timeout reproducible by setting timeout to 8s (instead of the
default 10s) for the duration of that test.

Make the test-case more stable by fixing all timeouts caused by setting
timeout to 5, either by adding with_timeout_factor, or increasing its factor.

Tested on x86_64-linux.  Also tested in parallel with stress -c 5, to simulate
a busy system in another way.

Committed to trunk.

Thanks,
- Tom

[gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

gdb/testsuite/ChangeLog:

2021-04-30  Tom de Vries  <tdevries@suse.de>

	* gdb.mi/mi-sym-info.exp: Add with_timeout_factor, and increase
	existing timeout factors.

---
 gdb/testsuite/gdb.mi/mi-sym-info.exp | 70 +++++++++++++++++++-----------------
 1 file changed, 37 insertions(+), 33 deletions(-)

diff --git a/gdb/testsuite/gdb.mi/mi-sym-info.exp b/gdb/testsuite/gdb.mi/mi-sym-info.exp
index f7f574aaeae..18f85182a7b 100644
--- a/gdb/testsuite/gdb.mi/mi-sym-info.exp
+++ b/gdb/testsuite/gdb.mi/mi-sym-info.exp
@@ -55,42 +55,46 @@ set type_syms \
 
 # Fetch all functions, variables and types without any non-debug
 # symbols.
-set testname "List all functions from debug information only"
-set cmd "111-symbol-info-functions"
-set state 0
-gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
-    -re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
-	if { $state == 0 } { incr state }
-	exp_continue
-    }
-    -re ",${symtab_re}" {
-	exp_continue
-    }
-    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
-	if { $state == 1 } {
-	    pass $gdb_test_name
-	} else {
-	    fail $gdb_test_name
+with_timeout_factor 2 {
+    set testname "List all functions from debug information only"
+    set cmd "111-symbol-info-functions"
+    set state 0
+    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
+	-re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
+	    if { $state == 0 } { incr state }
+	    exp_continue
+	}
+	-re ",${symtab_re}" {
+	    exp_continue
+	}
+	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
+	    if { $state == 1 } {
+		pass $gdb_test_name
+	    } else {
+		fail $gdb_test_name
+	    }
 	}
     }
 }
 
-set testname "List all variables from debug information only"
-set cmd "112-symbol-info-variables"
-set state 0
-gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
-    -re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
-	if { $state == 0 } { incr state }
-	exp_continue
-    }
-    -re ",${symtab_re}" {
-	exp_continue
-    }
-    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
-	if { $state == 1 } {
-	    pass $gdb_test_name
-	} else {
-	    fail $gdb_test_name
+with_timeout_factor 2 {
+    set testname "List all variables from debug information only"
+    set cmd "112-symbol-info-variables"
+    set state 0
+    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
+	-re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
+	    if { $state == 0 } { incr state }
+	    exp_continue
+	}
+	-re ",${symtab_re}" {
+	    exp_continue
+	}
+	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
+	    if { $state == 1 } {
+		pass $gdb_test_name
+	    } else {
+		fail $gdb_test_name
+	    }
 	}
     }
 }
@@ -150,7 +154,7 @@ gdb_test_multiple $cmd ${testname} -prompt "${mi_gdb_prompt}$" {
     }
 }
 
-with_timeout_factor 2 {
+with_timeout_factor 4 {
     set testname "List all variables"
     set cmd "115-symbol-info-variables --include-nondebug"
     set state 0

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Luis Machado via Gdb-patches]

Wouldn't it be more reliable to do line-by-line matching instead of 
sprinkling timeouts across the test? Or so I've been told.

This doesn't seem to be an instance where GDB is taking too long, but 
rather that the MI output is very verbose, right?

On 4/30/21 6:27 AM, Tom de Vries wrote:
> Hi,
> 
> Once in a while, I run into this timeout:
> ...
> FAIL: gdb.mi/mi-sym-info.exp: List all variables from debug information \
>    only (timeout)
> ...
> 
> I can make the timeout reproducible by setting timeout to 8s (instead of the
> default 10s) for the duration of that test.
> 
> Make the test-case more stable by fixing all timeouts caused by setting
> timeout to 5, either by adding with_timeout_factor, or increasing its factor.
> 
> Tested on x86_64-linux.  Also tested in parallel with stress -c 5, to simulate
> a busy system in another way.
> 
> Committed to trunk.
> 
> Thanks,
> - Tom
> 
> [gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts
> 
> gdb/testsuite/ChangeLog:
> 
> 2021-04-30  Tom de Vries  <tdevries@suse.de>
> 
> 	* gdb.mi/mi-sym-info.exp: Add with_timeout_factor, and increase
> 	existing timeout factors.
> 
> ---
>   gdb/testsuite/gdb.mi/mi-sym-info.exp | 70 +++++++++++++++++++-----------------
>   1 file changed, 37 insertions(+), 33 deletions(-)
> 
> diff --git a/gdb/testsuite/gdb.mi/mi-sym-info.exp b/gdb/testsuite/gdb.mi/mi-sym-info.exp
> index f7f574aaeae..18f85182a7b 100644
> --- a/gdb/testsuite/gdb.mi/mi-sym-info.exp
> +++ b/gdb/testsuite/gdb.mi/mi-sym-info.exp
> @@ -55,42 +55,46 @@ set type_syms \
>   
>   # Fetch all functions, variables and types without any non-debug
>   # symbols.
> -set testname "List all functions from debug information only"
> -set cmd "111-symbol-info-functions"
> -set state 0
> -gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
> -    -re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
> -	if { $state == 0 } { incr state }
> -	exp_continue
> -    }
> -    -re ",${symtab_re}" {
> -	exp_continue
> -    }
> -    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
> -	if { $state == 1 } {
> -	    pass $gdb_test_name
> -	} else {
> -	    fail $gdb_test_name
> +with_timeout_factor 2 {
> +    set testname "List all functions from debug information only"
> +    set cmd "111-symbol-info-functions"
> +    set state 0
> +    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
> +	-re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
> +	    if { $state == 0 } { incr state }
> +	    exp_continue
> +	}
> +	-re ",${symtab_re}" {
> +	    exp_continue
> +	}
> +	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
> +	    if { $state == 1 } {
> +		pass $gdb_test_name
> +	    } else {
> +		fail $gdb_test_name
> +	    }
>   	}
>       }
>   }
>   
> -set testname "List all variables from debug information only"
> -set cmd "112-symbol-info-variables"
> -set state 0
> -gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
> -    -re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
> -	if { $state == 0 } { incr state }
> -	exp_continue
> -    }
> -    -re ",${symtab_re}" {
> -	exp_continue
> -    }
> -    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
> -	if { $state == 1 } {
> -	    pass $gdb_test_name
> -	} else {
> -	    fail $gdb_test_name
> +with_timeout_factor 2 {
> +    set testname "List all variables from debug information only"
> +    set cmd "112-symbol-info-variables"
> +    set state 0
> +    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
> +	-re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
> +	    if { $state == 0 } { incr state }
> +	    exp_continue
> +	}
> +	-re ",${symtab_re}" {
> +	    exp_continue
> +	}
> +	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
> +	    if { $state == 1 } {
> +		pass $gdb_test_name
> +	    } else {
> +		fail $gdb_test_name
> +	    }
>   	}
>       }
>   }
> @@ -150,7 +154,7 @@ gdb_test_multiple $cmd ${testname} -prompt "${mi_gdb_prompt}$" {
>       }
>   }
>   
> -with_timeout_factor 2 {
> +with_timeout_factor 4 {
>       set testname "List all variables"
>       set cmd "115-symbol-info-variables --include-nondebug"
>       set state 0
> 

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[tdevries]

On 2021-04-30 14:55, Luis Machado wrote:
> Wouldn't it be more reliable to do line-by-line matching instead of
> sprinkling timeouts across the test?

There are not many lines, but very long lines.  The long lines are read 
in bit by bit, but it just takes a long time to start producing them.

That can only be dealt with using timeouts.

Thanks,
- Tom

> Or so I've been told.
> 
> This doesn't seem to be an instance where GDB is taking too long, but
> rather that the MI output is very verbose, right?
> 
> On 4/30/21 6:27 AM, Tom de Vries wrote:
>> Hi,
>> 
>> Once in a while, I run into this timeout:
>> ...
>> FAIL: gdb.mi/mi-sym-info.exp: List all variables from debug 
>> information \
>>    only (timeout)
>> ...
>> 
>> I can make the timeout reproducible by setting timeout to 8s (instead 
>> of the
>> default 10s) for the duration of that test.
>> 
>> Make the test-case more stable by fixing all timeouts caused by 
>> setting
>> timeout to 5, either by adding with_timeout_factor, or increasing its 
>> factor.
>> 
>> Tested on x86_64-linux.  Also tested in parallel with stress -c 5, to 
>> simulate
>> a busy system in another way.
>> 
>> Committed to trunk.
>> 
>> Thanks,
>> - Tom
>> 
>> [gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against 
>> timeouts
>> 
>> gdb/testsuite/ChangeLog:
>> 
>> 2021-04-30  Tom de Vries  <tdevries@suse.de>
>> 
>> 	* gdb.mi/mi-sym-info.exp: Add with_timeout_factor, and increase
>> 	existing timeout factors.
>> 
>> ---
>>   gdb/testsuite/gdb.mi/mi-sym-info.exp | 70 
>> +++++++++++++++++++-----------------
>>   1 file changed, 37 insertions(+), 33 deletions(-)
>> 
>> diff --git a/gdb/testsuite/gdb.mi/mi-sym-info.exp 
>> b/gdb/testsuite/gdb.mi/mi-sym-info.exp
>> index f7f574aaeae..18f85182a7b 100644
>> --- a/gdb/testsuite/gdb.mi/mi-sym-info.exp
>> +++ b/gdb/testsuite/gdb.mi/mi-sym-info.exp
>> @@ -55,42 +55,46 @@ set type_syms \
>>     # Fetch all functions, variables and types without any non-debug
>>   # symbols.
>> -set testname "List all functions from debug information only"
>> -set cmd "111-symbol-info-functions"
>> -set state 0
>> -gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
>> -    -re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
>> -	if { $state == 0 } { incr state }
>> -	exp_continue
>> -    }
>> -    -re ",${symtab_re}" {
>> -	exp_continue
>> -    }
>> -    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
>> -	if { $state == 1 } {
>> -	    pass $gdb_test_name
>> -	} else {
>> -	    fail $gdb_test_name
>> +with_timeout_factor 2 {
>> +    set testname "List all functions from debug information only"
>> +    set cmd "111-symbol-info-functions"
>> +    set state 0
>> +    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
>> +	-re "111\\^done,symbols=\{debug=\\\[${symtab_re}" {
>> +	    if { $state == 0 } { incr state }
>> +	    exp_continue
>> +	}
>> +	-re ",${symtab_re}" {
>> +	    exp_continue
>> +	}
>> +	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
>> +	    if { $state == 1 } {
>> +		pass $gdb_test_name
>> +	    } else {
>> +		fail $gdb_test_name
>> +	    }
>>   	}
>>       }
>>   }
>>   -set testname "List all variables from debug information only"
>> -set cmd "112-symbol-info-variables"
>> -set state 0
>> -gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
>> -    -re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
>> -	if { $state == 0 } { incr state }
>> -	exp_continue
>> -    }
>> -    -re ",${symtab_re}" {
>> -	exp_continue
>> -    }
>> -    -re "\\\]\}\r\n${mi_gdb_prompt}$" {
>> -	if { $state == 1 } {
>> -	    pass $gdb_test_name
>> -	} else {
>> -	    fail $gdb_test_name
>> +with_timeout_factor 2 {
>> +    set testname "List all variables from debug information only"
>> +    set cmd "112-symbol-info-variables"
>> +    set state 0
>> +    gdb_test_multiple $cmd $testname -prompt "${mi_gdb_prompt}$" {
>> +	-re "112\\^done,symbols=\{debug=\\\[${symtab_re}" {
>> +	    if { $state == 0 } { incr state }
>> +	    exp_continue
>> +	}
>> +	-re ",${symtab_re}" {
>> +	    exp_continue
>> +	}
>> +	-re "\\\]\}\r\n${mi_gdb_prompt}$" {
>> +	    if { $state == 1 } {
>> +		pass $gdb_test_name
>> +	    } else {
>> +		fail $gdb_test_name
>> +	    }
>>   	}
>>       }
>>   }
>> @@ -150,7 +154,7 @@ gdb_test_multiple $cmd ${testname} -prompt 
>> "${mi_gdb_prompt}$" {
>>       }
>>   }
>>   -with_timeout_factor 2 {
>> +with_timeout_factor 4 {
>>       set testname "List all variables"
>>       set cmd "115-symbol-info-variables --include-nondebug"
>>       set state 0
>> 

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Simon Marchi via Gdb-patches]

On 2021-04-30 8:55 a.m., Luis Machado via Gdb-patches wrote:
> Wouldn't it be more reliable to do line-by-line matching instead of sprinkling timeouts across the test? Or so I've been told.
> 
> This doesn't seem to be an instance where GDB is taking too long, but rather that the MI output is very verbose, right?

From what I can see, it's a case of GDB thinking for a long time
(gathering symbols) before outputting anything.  You can see it
by having a

  $ tail -F testsuite/gdb.log

on the side, while you run the test.

Another one that I found times out in a similar way on my machine is
gdb.base/info-os.exp.

Simon

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Luis Machado via Gdb-patches]

On 4/30/21 10:06 AM, Simon Marchi wrote:
> On 2021-04-30 8:55 a.m., Luis Machado via Gdb-patches wrote:
>> Wouldn't it be more reliable to do line-by-line matching instead of sprinkling timeouts across the test? Or so I've been told.
>>
>> This doesn't seem to be an instance where GDB is taking too long, but rather that the MI output is very verbose, right?
> 
>  From what I can see, it's a case of GDB thinking for a long time
> (gathering symbols) before outputting anything.  You can see it
> by having a
> 
>    $ tail -F testsuite/gdb.log
> 
> on the side, while you run the test.
> 
> Another one that I found times out in a similar way on my machine is
> gdb.base/info-os.exp.
> 
> Simon
> 

Fair enough. But I also see the output being 113K chars in one case, no 
line breaks. I think these instances of very long lines are something to 
be dealt with.

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Simon Marchi via Gdb-patches]

On 2021-04-30 9:20 a.m., Luis Machado wrote:> On 4/30/21 10:06 AM, Simon Marchi wrote:
>> On 2021-04-30 8:55 a.m., Luis Machado via Gdb-patches wrote:
>>> Wouldn't it be more reliable to do line-by-line matching instead of sprinkling timeouts across the test? Or so I've been told.
>>>
>>> This doesn't seem to be an instance where GDB is taking too long, but rather that the MI output is very verbose, right?
>>
>>  From what I can see, it's a case of GDB thinking for a long time
>> (gathering symbols) before outputting anything.  You can see it
>> by having a
>>
>>    $ tail -F testsuite/gdb.log
>>
>> on the side, while you run the test.
>>
>> Another one that I found times out in a similar way on my machine is
>> gdb.base/info-os.exp.
>>
>> Simon
>>
> 
> Fair enough. But I also see the output being 113K chars in one case, no line breaks. I think these instances of very long lines are something to be dealt with.

Yeah, good point.  If GDB takes 6 seconds to think and Dejagnu takes 6
seconds to read the long input, the timeout is a result of the
combination of both, so it wouldn't hurt to parse item by item.  It's a
bit more work to parse one item at the time, but in the end I think it
also helps when you need to debug the test, as you can print a little
something after parsing each item and know where things went wrong.

Simon

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Luis Machado via Gdb-patches]

On 4/30/21 10:28 AM, Simon Marchi wrote:
> On 2021-04-30 9:20 a.m., Luis Machado wrote:> On 4/30/21 10:06 AM, Simon Marchi wrote:
>>> On 2021-04-30 8:55 a.m., Luis Machado via Gdb-patches wrote:
>>>> Wouldn't it be more reliable to do line-by-line matching instead of sprinkling timeouts across the test? Or so I've been told.
>>>>
>>>> This doesn't seem to be an instance where GDB is taking too long, but rather that the MI output is very verbose, right?
>>>
>>>   From what I can see, it's a case of GDB thinking for a long time
>>> (gathering symbols) before outputting anything.  You can see it
>>> by having a
>>>
>>>     $ tail -F testsuite/gdb.log
>>>
>>> on the side, while you run the test.
>>>
>>> Another one that I found times out in a similar way on my machine is
>>> gdb.base/info-os.exp.
>>>
>>> Simon
>>>
>>
>> Fair enough. But I also see the output being 113K chars in one case, no line breaks. I think these instances of very long lines are something to be dealt with.
> 
> Yeah, good point.  If GDB takes 6 seconds to think and Dejagnu takes 6
> seconds to read the long input, the timeout is a result of the
> combination of both, so it wouldn't hurt to parse item by item.  It's a
> bit more work to parse one item at the time, but in the end I think it
> also helps when you need to debug the test, as you can print a little
> something after parsing each item and know where things went wrong.

What I'm unsure about is if the MI protocol cares about line breaks or 
not. If not, there is no reason we should be putting out such long line, 
as it is hard on the test infrastructure.

> 
> Simon
> 

Re: [committed][gdb/testsuite] Make gdb.mi/mi-sym-info.exp more robust against timeouts

[Simon Marchi via Gdb-patches]

On 2021-04-30 9:34 a.m., Luis Machado wrote:
> What I'm unsure about is if the MI protocol cares about line breaks or not. If not, there is no reason we should be putting out such long line, as it is hard on the test infrastructure.

From what I remember, I don't think there can be newlines in the output.
Each output record is on its own line.

Simon