Bug #44834 for Net-Appliance-Session: pathologic behaviour with "show ip bgp"

Mon Apr 06 18:32:31 2009 d.thomas [...] its.uq.edu.au - Ticket created

Subject:

pathologic behaviour with "show ip bgp"

I should have reported this a few weeks ago when I installed the current version along with module dependencies under perl 5.10 on FreeBSD 7.1 I wrote a script to parse the output of "show ip bgp" from a cisco router which produced sligthtly over 10K lines, but the script took 260 seconds to run at 100% CPU. By way of contrast, the script could also fetch the table using Net::SSH2 which took 4 seconds with little CPU. I reduced the runtime by limiting max_buffer_size (resulting in truncated input). # and DProf produced # Total Elapsed Time = 4.215710 Seconds # User+System Time = 3.846182 Seconds # Exclusive Times # %Time ExclSec CumulS #Calls sec/call Csec/c Name # 75.7 2.912 4.055 102 0.0285 0.0398 Net::Telnet::waitfor # 8.89 0.342 0.716 99 0.0035 0.0072 Devel::StackTrace::_record_caller_ # data # 4.47 0.172 0.172 19744 0.0000 0.0000 UNIVERSAL::isa # 3.51 0.135 0.271 99 0.0014 0.0027 Carp::short_error_loc # 3.04 0.117 0.157 19998 0.0000 0.0000 overload::AddrRef # 2.47 0.095 0.136 34254 0.0000 0.0000 Carp::trusts # 1.20 0.046 0.046 39897 0.0000 0.0000 Scalar::Util::blessed Execution with the full table dropped to a few seconds after changing prompt to '/[\/a-zA- Z0-9._-]+#$/' I'm not saying the default prompt should be changed unless that is sensible, but maybe this behaviour should get some mention in the docs ? thanks Danny

Wed Apr 08 04:07:48 2009 OLIVER [...] cpan.org - Taken

Wed Apr 08 04:07:52 2009 OLIVER [...] cpan.org - Status changed from 'new' to 'open'

Wed Apr 08 04:21:35 2009 OLIVER [...] cpan.org - Correspondence added

Hi Danny, On Mon Apr 06 18:32:31 2009, d.thomas@its.uq.edu.au wrote: Show quoted text

> I should have reported this a few weeks ago when I installed the > current version

All feedback most definitely appreciated, whenever it's reported! :-) So I have some points to clarify below, hopefully quick for you to answer, then I'll try to find the time to look at this. We don't carry a full bgp table but I've run other commands in the past with large output, such as show tech-support. Either I wasn't paying attention, or something is different about openssh on Debian, because I don't recall such issues. However, I do remember having to increase the output buffer in Net::Telnet to something large like a megabyte to be able to slurp the command output in one go. Anyway... First, can you let me know whether you were using SSH or Telnet (or even Serial) to connect to the device, and which external helper app (e.g. openssh)? Show quoted text

> I wrote a script to parse the output of "show ip bgp" from a cisco > router which produced > sligthtly over 10K lines, but the script took 260 seconds to run at > 100% CPU.

Can you clarify which CPU was pegged, the router's or the ssh client's? Show quoted text

> By way of > contrast, the script could also fetch the table using Net::SSH2 which > took 4 seconds with > little CPU. I reduced the runtime by limiting max_buffer_size > (resulting in truncated input).

My pea-brain is a bit confused here - in which toolkit is the max_buffer_size option? I don't recall it as a Net::Telnet option, nor openssh. Also could you expand on what you mean by 'truncated input'? Show quoted text

> Execution with the full table dropped to a few seconds after changing > prompt to '/[\/a-zA- > Z0-9._-]+#$/'

Ah, very interesting - so you suspect the prompt regexp might be the cause? You know I did have some ideas for improving the prompts - using a bunch of more fine grained ones in each device mode rather than one all-purpose regex. This is something I'll definitely test out now you've raised the issue. Show quoted text

> maybe this behaviour should get some mention in the docs ?

I agree performing this way sucks, and certainly unless we find a bug to fix which causes this behaviour then it needs a mention. I'll pop it on my TODO list. For info, I am working on version 2.x of the module. It's more of a refactor - adding support for plugins and so on, rather than intending to fix such performance issues, but I'll see what else can be folded in. regards, oliver.

Wed Apr 08 21:41:10 2009 d.thomas [...] its.uq.edu.au - Correspondence added

From:

d.thomas [...] its.uq.edu.au

<got truncation cause I didn't attach file> openssh client CPU maxxed out Show quoted text

>> I reduced the runtime by limiting max_buffer_size

> > (resulting in truncated input).

> > My pea-brain is a bit confused here - in which toolkit is the > max_buffer_size option? I don't recall it as a Net::Telnet option, nor > openssh.

when I first ran the script it gave an error message saying input was larger than max_buffer_size. I think it's in Net:::Telnet Show quoted text

> Also could you expand on what you mean by 'truncated input'?

I wanted input to only take a few seconds and be comparable to show running config so I set max_buffer_size to 100K. Of course I got the same error message so the part of the script that processed the bgp table never ran. I also wanted a short run-time profiling. Show quoted text

> > Execution with the full table dropped to a few seconds after changing > > prompt to '/[\/a-zA- > > Z0-9._-]+#$/'

> > Ah, very interesting - so you suspect the prompt regexp might be the > cause?

yes, but related to the format of the bgp table. Is it possible to bypass the prompt processing altogether. My script is pretty strict on the bgp format, so any prompt appearing in it would cause the script to barf.

Thu Dec 30 16:15:48 2010 OLIVER [...] cpan.org - Correspondence added

Hello again Danny, On Mon Apr 06 18:32:31 2009, d.thomas@its.uq.edu.au wrote: Show quoted text

> I wrote a script to parse the output of "show ip bgp" from a cisco > router which produced > sligthtly over 10K lines, but the script took 260 seconds to run at > 100% CPU. By way of > contrast, the script could also fetch the table using Net::SSH2 which > took 4 seconds with > little CPU. I reduced the runtime by limiting max_buffer_size > (resulting in truncated input).

I think this is, sadly, not going to be fixable in the current design of Net::Telnet based Net::Appliance::Session. However I'm still working on an alternative replacement and will be sure to test this case against a public route server. The general cause is the way that Net::Telnet handles prompt matching, I think: it matches on every line received and the whole output received, so as you get more output, it gets slower and slower. This doesn't seem to interact well with my use of openssh, either - again, another thing to test. Sorry for the lack of progress on this. regards, oliver.

Thu Dec 30 16:15:49 2010 OLIVER [...] cpan.org - Status changed from 'open' to 'resolved'