Re: ***UNCHECKED*** RE: Strange behavior of Ncurses

[Thomas Dickey]

On Wed, Oct 16, 2024 at 01:54:39PM +0000, Urban Söderberg wrote:
> Hi Thomas & Branden,
>  
> We have activated trace in Ncurses.
>  
> Attached are two files:
> space_trace_printout.zip
> nr_trace_printout.zip
> Unzip with password: 123456
> Ncurses-functions used can be seen as well as $TERM.

I see - TERM=vt100, and 38400 baudrate.

As an aside, vt100 has padding (because it's for the real hardware terminal).
If you're using a terminal emulator, you'll get some unwanted delays from
just that.  You can suppress the delays with the environment variable
NCURSES_NO_PADDING

In the vt100 entry, clear, cup, cuf1, ed, el, el1 all have time delays,
and if you're moving the cursor or clearing the screen a lot, that adds up:

        clear=\E[H\E[J$<50>, cr=\r, csr=\E[%i%p1%d;%p2%dr,
        cub=\E[%p1%dD, cub1=^H, cud=\E[%p1%dB, cud1=\n,
        cuf=\E[%p1%dC, cuf1=\E[C$<2>,
        cup=\E[%i%p1%d;%p2%dH$<5>, cuu=\E[%p1%dA,
        cuu1=\E[A$<2>, ed=\E[J$<50>, el=\E[K$<3>, el1=\E[1K$<3>,

Alternatively, if that's some real hardware, it may not scroll very well,
and _that_ could be the problem. :-)

These traces say the screensize is 69 by 185 (rather wide),
and that ncurses is initializing the terminal to scroll the whole screen.
The initialization didn't show in the earlier examples.
  
> First one, space_trace_printout, is covering the printout which we have 
> issues with, where we see the clear to end of screen escape sequence, move 
> cursor to first line,  followed by a lot of scrap text.
> This trace-log is also bigger than the other one.
>  
> Second one, nr_trace_printout, no issue is seen, each line starting with a 
> number, making each line unique.
>  
> A look at space_trace_printout:
> Hard to us to interpret entries, but we noticed something, nc_scroll_optimize 
> (at line: 67364):
> .
> .
> newscr[65]  30 31 ='                             46   '
> newscr[66]  16 31 ='                PRC-610      229  '
> newscr[67]  16 31 ='                             423  '
> newscr[68]  29 31 ='                                  '
> + + + + called {_nc_signal_handler(0)
> + + + + return }
> + + + + called {_nc_scroll_optimize(0x17fb4f0)
> virt  -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 
> -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 
> -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1
> + + + + return }
> GoTo(0x17fb4f0, 68, 0) from (68, 184)
> + + + + called {_nc_tinfo_mvcur(0x17fb4f0,68,184,68,0)
> + + + + + called {tparm("\e[%i%p1%d;%p2%dH$<5>", 68, 0)
> + + + + + return }"\e[69;1H$<5>"
> + + + + + called {tparm("\e[%p1%dD", 184)
> + + + + + return }"\e[184D"
> + + + + + called {tparm("\e[%p1%dB", 68)
> + + + + + return }"\e[68B"
> tputs(mvcur = "\r", 1, _nc_outch) called
> + + + + return }0
> tputs(clr_eos = "\e[J$<50>", 1, _nc_outch) called
> Transforming lines, nonempty 68
> + + + + called {TransformLine(0x17fb4f0, 0)
> GoTo(0x17fb4f0, 0, 16) from (68, 0)
> + + + + + called {_nc_tinfo_mvcur(0x17fb4f0,68,0,0,16)
> + + + + + + called {tparm("\e[%i%p1%d;%p2%dH$<5>", 0, 16)
> + + + + + + return }"\e[1;17H$<5>"
> tputs(mvcur = "\e[1;17H$<5>", 1, _nc_outch) called
> + + + + + return }0
> PutRange(0x17fb4f0, 0x1815310, 0x17ffd60, 0, 16, 31)
> EmitRange 7:{"PRC-610"}
> PutAttrChar({'P' = 0120}) at (0, 16)
> PutAttrChar({'R' = 0122}) at (0, 17)
> PutAttrChar({'C' = 0103}) at (0, 18)
> PutAttrChar({'-' = 055}) at (0, 19)
> .
> .
> 
> Compare this to the trace where the same text is printed, but
> nc_scroll_optimize (at line:  67041) behaves differently:
> .
> . 
> newscr[65]   0 32 ='0                             46   '
> newscr[66]   0 32 ='1                PRC-610      229  '
> newscr[67]   0 32 ='2                             423  '
> newscr[68]   0 32 ='                                   '
> + + + + called {_nc_signal_handler(0)
> + + + + return }
> + + + + called {_nc_scroll_optimize(0x1fbf4f0)
> new line 2 is hash-identical to old line 3 (unique)
> new line 5 is hash-identical to old line 6 (unique)
> new line 8 is hash-identical to old line 9 (unique)
> new line 11 is hash-identical to old line 12 (unique)
> new line 14 is hash-identical to old line 15 (unique)
> new line 17 is hash-identical to old line 18 (unique)
> new line 20 is hash-identical to old line 21 (unique)
> new line 23 is hash-identical to old line 24 (unique)
> new line 26 is hash-identical to old line 27 (unique)
> new line 29 is hash-identical to old line 30 (unique)
> new line 32 is hash-identical to old line 33 (unique)
> new line 35 is hash-identical to old line 36 (unique)
> new line 38 is hash-identical to old line 39 (unique)
> new line 41 is hash-identical to old line 42 (unique)
> new line 44 is hash-identical to old line 45 (unique)
> new line 47 is hash-identical to old line 48 (unique)
> new line 50 is hash-identical to old line 51 (unique)
> new line 53 is hash-identical to old line 54 (unique)
> new line 56 is hash-identical to old line 57 (unique)
> new line 59 is hash-identical to old line 60 (unique)
> new line 62 is hash-identical to old line 63 (unique)
> new line 65 is hash-identical to old line 66 (unique)
> connected new line 1 to old line 2 (backward continuation)
> connected new line 0 to old line 1 (backward continuation)
> connected new line 3 to old line 4 (forward continuation)
> connected new line 4 to old line 5 (backward continuation)
> connected new line 6 to old line 7 (forward continuation)
> connected new line 7 to old line 8 (backward continuation)
> .
> .
>  
> Why does _nc_scroll_optimize behave differently in those cases? We would 
> expect it to behave the same.
> Is this normal behavior? Can this optimization be disabled, or is it 
> something we can do/configure to avoid this behavior?

The scrolling optimization compares the whole line, because (it usually works)
vt100-style scrolling regions affect the whole line.  Lines with numbers are
going to look different -- and it'll cause ncurses to give up on that faster
than the other example.

The space_trace_printout example says that it's calling the optimization
function 275 times because wrefresh is called that many times, and _that_
happens after adding a newline (causing the scrolling).  The trace seems
to show that it's recognizing that the lines shift by one - okay.

You asked about the backspaces - I see an example in this chunk,
which says that it's updating a line partially by jumping from
1,32 to 2,29, and the relevant capability is cursor_left (which
in the vt100 entry happens to be a backspace because it's shorter
than \E[D (1 byte vs 3)

        {TransformLine(0x17fb4f0, 2)
        GoTo(0x17fb4f0, 2, 29) from (1, 32)
        + + + + + called {_nc_tinfo_mvcur(0x17fb4f0,1,32,2,29)
        + + + + + + called {tparm("\e[%i%p1%d;%p2%dH$<5>", 2, 29)
        + + + + + + return }"\e[3;30H$<5>"
        + + + + + + called {tparm("\e[%p1%dB", 1)
        + + + + + + return }"\e[1B"
        + + + + + + called {tparm("\e[%p1%dD", 3)
        + + + + + + return }"\e[3D"
        + + + + + + called {tparm("\e[%p1%dB", 1)
        + + + + + + return }"\e[1B"
        + + + + + + called {tparm("\e[%p1%dC", 29)
        + + + + + + return }"\e[29C"
        + + + + + + called {tparm("\e[%p1%dB", 2)
        + + + + + + return }"\e[2B"
        + + + + + + called {tparm("\e[%p1%dC", 29)
        + + + + + + return }"\e[29C"
        + + + + + + called {tparm("\e[%p1%dB", 1)
        + + + + + + return }"\e[1B"
        + + + + + + called {tparm("\e[%p1%dD", 3)
        + + + + + + return }"\e[3D"
        tputs(mvcur = "\n\b\b\b", 1, _nc_outch) called
        + + + + + return }0
        PutRange(0x17fb4f0, 0x18158f0, 0x18089e0, 2, 29, 31)
        EmitRange 3:{"2  "}
        PutAttrChar({'2' = 062}) at (2, 29)
        PutAttrChar({' ' = 040}) at (2, 30)
        PutAttrChar({' ' = 040}) at (2, 31)
        + + + + return }

But determining whether you need the padding is easier than determining
if that terminal is inefficient with scrolling or partial line updates :-)
  
> Best regards
> Urban
> 
> -----Original Message-----
> From: Thomas Dickey <dickey@his.com> 
> Sent: Saturday, 12 October 2024 15:53
> To: G. Branden Robinson <g.branden.robinson@gmail.com>
> Cc: Urban Söderberg <Urban.Soderberg@knowit.se>; Ncurses Mailing List 
> <bug-ncurses@gnu.org>; Gustav W. Uppenberg <gustav.uppenberg@knowit.se>; 
> Roxana Prelipceanu <roxana.prelipceanu@knowit.se>; Pauline Littbrand 
> <pauline.littbrand@knowit.se>; Kristoffer Mattila 
> <kristoffer.mattila@knowit.se>
> Subject: Re: Strange behavior of Ncurses
> 
> [Du får inte e-post ofta från dickey@his.com. Läs om varför det här är 
> viktigt på https://aka.ms/LearnAboutSenderIdentification ]
> 
> ----- Original Message -----
> | From: "G. Branden Robinson" <g.branden.robinson@gmail.com>
> | To: "Urban Söderberg" <Urban.Soderberg@knowit.se>
> | Cc: "Thomas Dickey" <dickey@his.com>, "Ncurses Mailing List" 
> <bug-ncurses@gnu.org>, "Gustav W. Uppenberg"
> | <gustav.uppenberg@knowit.se>, "Roxana Prelipceanu" 
> <roxana.prelipceanu@knowit.se>, "Pauline Littbrand"
> | <pauline.littbrand@knowit.se>, "Kristoffer Mattila" 
> | <kristoffer.mattila@knowit.se>
> | Sent: Friday, October 11, 2024 2:11:02 PM
> | Subject: Re: Strange behavior of Ncurses
> 
> | At 2024-10-11T13:18:16+0000, Urban Söderberg wrote:
> |> We did strace on our application and could see that character 
> |> sequences are caused by ncurses.
> |>
> |> File: dev-pts-2-trace3.log
> |> Printout lines starting with spaces.
> |> We can see several lines like this:
> |> [pid 2001732] 12:04:54.106158 write(1</dev/pts/2<char 136:2>>, 
> |> "\33[J\33[1;17H",
> |> 10) = 10 <0.000015>
> |> This causes issues.
> |
> | Just FYI, the sequence in question,
> |
> | \33[J
> |
> | looks like "CSI J", the ECMA-48 escape sequence for clearing the 
> | screen, [1] and
> |
> | \33[1;17H
> |
> | looks like "CSI H", the ECMA-48 escape sequence for (absolute) cursor 
> | positioning ("CUP").
> |
> | A copy of ECMA-48 can be found here:
> |
> | https://www.ecma-international.org/wp-content/uploads/ECMA-48_5th_edit
> | ion_june_1991.pdf
> |
> | If ncurses is emitting those sequences, it is likely because the 
> | terminfo database entry for the value of $TERM on the system records 
> | that they are how to manifest the operations in question.
> 
> Actually, ncurses could emit those strings, but because ncurses optimizes 
> cursor movement, the only way it would be sending the cursor to the right 
> margin and _then_ going to the next line would be if the application were 
> forcing the screen to be updated and causing ncurses to wait for keyboard 
> input.  That's kind of unlikely.
> 
> It's a lot more likely that the application is a low-level terminfo or 
> termcap application which does no optimization.  If the application is 
> stripped and statically linked, it would take some work to prove this, but if 
> it's not, then someone could use "nm" to list the functions it uses.
> 
> If it's using initscr or newterm, that says it could be using cursor 
> optimization.
> It's still possible that the developer bypasses all of that (think 
> "printf"...).
> 
> strace won't tell me any of that.  "nm" or "nm -D" is the way to start 
> collecting data.
> 
> |
> | Is your $TERM correct?
> |
> | Regards,
> | Branden
> |
> | [1] ECMA-48 calls it "ERASE IN PAGE"; the ctlseqs.ms document calls it
> |     "Erase in Display".  Both abbreviate it as "ED".
> 
> --
> Thomas E. Dickey <dickey@invisible-island.net> https://invisible-island.net
> 




-- 
Thomas E. Dickey <dickey@invisible-island.net>
https://invisible-island.net

signature.asc
Description: PGP signature