[j-nsp] why is "show log messages | last 10" so slow?

[Anderson, Charles R]

Why is "show log messages | last 10" so slow with a large log file when I can go to the shell and run "tail -10 /var/log/messages" much more quickly? Maybe JUNOS can borrow the implementation of the "tail" command to make it quicker.
_______________________________________________
juniper-nsp mailing list juniper-***@puck.nether.net
https://puck.nether.net/mailman/listinfo/juniper-nsp

[Hugo Slabbert]

Post by Anderson, Charles R
Why is "show log messages | last 10" so slow with a large log file when I
can go to the shell and run "tail -10 /var/log/messages" much more
quickly?

Because it's an action that is done after the pipe rather than being the
action itself, so it's equivalent to `cat /var/log/messages | tail -n 10`
not directly to `tail -n 10 /var/log/messages`. It's a generic pipe action
that can be applied to any text output, e.g. the output of a regular
operational "show" command, but it's not a top-level command that does file
processing itself like `tail` can.

Post by Anderson, Charles R
Maybe JUNOS can borrow the implementation of the "tail" command to make it
quicker.

They'd have to add a new top-level command or perhaps add a parameter to
the `file show` operation, I'd think. Probably doable, but not sure how
much traction the feature request would get.

[Saku Ytti]

I suspect this change would be difficult one.

XML RPC is the first class citizen, CLI is generated from the XML.

Naively we'd might think the CLI forks cat and this is simple fix. But
because JunOS is actually designed right in this respect, this is not
what it does.


***@r24.labxtx01.us.bb-re0> show log messages | display xml rpc
<rpc-reply xmlns:junos="http://xml.juniper.net/junos/18.1I0/junos">
<rpc>
<get-log>
<filename>messages</filename>
</get-log>
</rpc>
<cli>
<banner>{master}</banner>
</cli>
</rpc-reply>



So this is the information the RPC backend gets. Curiously:

***@r24.labxtx01.us.bb-re0> show log messages | last 50 |display xml rpc
<rpc-reply xmlns:junos="http://xml.juniper.net/junos/18.1I0/junos">
<rpc>
<get-log>
<filename>messages</filename>
</get-log>
</rpc>
<rpc>
<get-log>
<filename>messages</filename>
</get-log>
</rpc>
<cli>
<banner>{master}</banner>
</cli>
</rpc-reply>

{master}
***@r24.labxtx01.us.bb-re0>


Dunno why the 'get-log' is there twice. However, the salient point is,
we're not passing the 'last 50' the RPC call, the backend has no
awareness of this. The 'last 50' is purely CLI construct. The
designers could have chosen that 'last N' is passed to RPC always as
an argument, and never implemented in CLI, and each RPC call has to
implement it. It is debatable which is the right call.

Changing this post-fact would be challenge, not only would they need
to start passing 'last N' as argument to RPC call, they'd also need
boolean in RPC reply to tell if 'last N' was honoured or not, so that
CLI could omit from doing it again when RPC call is implementing it.



Interestingly someone pointed out on another forum that 'show config'
is fast, while 'show config | count' it slow, implying some sort of
streaming. And sure enough 'show config | display xml rpc' does not
work, perhaps Juniper implemented optimisation where CLI does not use
RPC call for 'show config' to stream it?

Post by Hugo Slabbert

Post by Anderson, Charles R
Why is "show log messages | last 10" so slow with a large log file when I
can go to the shell and run "tail -10 /var/log/messages" much more
quickly?

Because it's an action that is done after the pipe rather than being the
action itself, so it's equivalent to `cat /var/log/messages | tail -n 10`
not directly to `tail -n 10 /var/log/messages`. It's a generic pipe action
that can be applied to any text output, e.g. the output of a regular
operational "show" command, but it's not a top-level command that does file
processing itself like `tail` can.

Post by Anderson, Charles R
Maybe JUNOS can borrow the implementation of the "tail" command to make it
quicker.

They'd have to add a new top-level command or perhaps add a parameter to
the `file show` operation, I'd think. Probably doable, but not sure how
much traction the feature request would get.
--
pgp key: B178313E | also on Signal
_______________________________________________
https://puck.nether.net/mailman/listinfo/juniper-nsp

[Phil Shafer]

Post by Saku Ytti
The 'last 50' is purely CLI construct. The
designers could have chosen that 'last N' is passed to RPC always as
an argument, and never implemented in CLI, and each RPC call has to
implement it. It is debatable which is the right call.

That's fairly accurate. Most of the UI pipes are implemented in
the CLI, allowing them to be used interactively, like the "m"
keystroke at the automore prompt being equivalent to the "match"
pipe, "e" == "except", etc:

---(Help for CLI automore)---
Clear all match and except strings: c or C
Display all line matching a regexp: m or M <string>
Display all lines except those matching a regexp: e or E <string>
Display this help text: h
Don't hold in automore at bottom of output: N
Hold in automore at bottom of output: H
Move down half display: TAB, d, or ^D
Move down one line: Enter, j, ^N, ^X, ^Z, or Down-Arrow
Move down one page: Space, f, ^F, or Right-Arrow
Move to bottom of output: G, ^E, or End
Move to top of output: g, ^A, or Home
Move up half display: u or ^U
Move up one line: k, Delete, Backspace, ^P, or Up-Arrow
Move up one page: b, ^B, or Left-Arrow
Quit automore: q, Q, ^K
Redraw display: ^L or ^R
Repeat a keystroke command 1 to 9 times: Meta-1..9
Repeat last search: n
Save output to a file: s or S <filename/url>
Search backwards thru the output: ?<string>
Search forwards thru the output: /<string>
---(End of Help)---

FWIW, I use this extensively to match/except my way to the source of
a problem, then clear to see the complete log.

For "last", this isn't really vital, but it's worth notice that the
display is really showing the <n> lines of the display, but the
complete display is buffered and available in automore, so you can
page backward ("b") through it. This means it's more like the G
in more/less, that "tail".

It also means the CLI goes thru the cost of recording the complete
input data set. If you want to avoid this cost, use the "no-more"
pipe:

***@cli> show log messages | last 5 | no-more
Oct 30 09:52:55 mgd[38686]: UI_DBASE_LOGIN_EVENT: User 'phil' entering configuration mode
Oct 30 09:52:59 mgd[38686]: UI_DBASE_LOGOUT_EVENT: User 'phil' exiting configuration mode
Oct 30 10:00:36 hassisd[4105]: CHASSISD_SNMP_TRAP6: SNMP trap generated: Power Supply failed (jnxContentsContainerIndex 2, jnxContentsL1Index 1, jnxContentsL2Index 0, jnxContentsL3Index 0, jnxContentsDescr PEM 0, jnxOperatingState/Temp 6)

Note that this tosses you back to the CLI prompt instead of keeping
you at the automore prompt.

Thanks,
Phil
_______________________________________________
juniper-nsp mailing list juniper-***@puck.nether.net
https://puck.nether.net/mailman/listinfo/juniper-nsp