Re: [RFA/testsuite] Workaround timeout in default.exp

[Daniel Jacobowitz <drow at false dot org>]

On Thu, May 20, 2004 at 06:14:43PM -0700, Joel Brobecker wrote:
> > If you're trying to debug expect matching, I recommend "exp_internal 1"
> > before the block (and maybe "exp_internal 0" after).  That will let you
> > see exactly what's going on, and why my crackpot theory is wrong :)
> 
> Nice command, that really helped understand better what was going on.
> 
> Roughly, it seems that what is hurting us is that expect is eating up
> the output from GDB reeeaaaal slooooowwww. Not expect's fault, I imagine,
> but by counting characters in the first few iterations, it looks like
> expect gets the output 12-15 characters at a time. It takes a total
> of 113 reads to fetch the entire command output, which contains ~9000
> characters, which makes around 80 chars per read.
> 
> And from watching it run and spit the expect debug data, it seems as if
> expect is getting slower and slower at each iteration. It looks like an
> algorithm that's not linear, but something exponential instead.
> 
> As an experiment, I tried increasing the timeout value to 600secs,
> and the test did complete successfully... After 18mins!
> 
> It seemed to be slowing down on the evaluation of one specific regexp:
> 
>         ".*\(gdb\) $"? no

So, it sounds like that's the problem.  I don't know why expect would
behave this terribly, but I do know something else: the regular
expression is not front-anchored.  So the leading .* does nothing.  You
may as well try removing it.  I bet that will also fix the speed
problem.

[I think there should be a \r\n in front of the "$gdb_prompt $" anyway,
don't you?  Wouldn't that fix the related problem?  Please try
replacing that pattern with "\r\n$gdb_prompt $".]

> So I uncommented it in gdb_test_multiple as follow, just to see what
> effect it would have:
> 
>         #  -re ".*$gdb_prompt $" {
>         #     if ![string match "" $message] then {
>         #       fail "$message"
>         #     }
>         #     set result 1
>         # }
> 
> You are going to be surprised. That specific test takes less than 40secs
> to run. The whole default.exp test takes a total of 1mn45secs.
> 
> And what's curious, even after have is that I still see expect try the
> same regexp. Before commenting out the code above, the sequence of
> regexp evaluations looked like:
> 
>         "Undefined[a-z]* command:.*\(gdb\) $"? no
>         "Ambiguous command.*\(gdb\) $"? no
>         "Program exited with code [0-9]+.*\(gdb\) $"? no
>         "EXIT code [0-9\r\n]+Program exited normally.*\(gdb\) $"? no
>         "The program is not being run.*\(gdb\) $"? no
>         ".*\(gdb\) $"? no
>         "<return>"? no
>         "\(y or n\) "? no
> 
> After, it was slightly transformed into:
> 
>         "Undefined[a-z]* command:.*\(gdb\) $"? no
>         "Ambiguous command.*\(gdb\) $"? no
>         "Program exited with code [0-9]+.*\(gdb\) $"? no
>         "EXIT code [0-9\r\n]+Program exited normally.*\(gdb\) $"? no
>         "The program is not being run.*\(gdb\) $"? no
>         "#"? no
>         ".*\(gdb\) $"? no
>         "<return>"? no
>         "\(y or n\) "? no
> 
> At this point, no comprendo anymore... :-/
> (where does the "#" come from, and why is the gdb_prompt check
> still there?)

'#' doesn't do what you think it does.

First of all, it is not an element of TCL syntax.  It's just a command
which does nothing.  Secondly, as a consequence, you can't use it where
you aren't expecting commands.  So what you did was match "#" {action
body is "-re"}, and then ".*\(gdb\) $" {note that there's no leading
-re now, so it is treated as an exact match instead of a regular
expression!}.

-- 
Daniel Jacobowitz