Subject: lib/36175: mismatch of LANG and mutt's charset leads to excrutiatingly slow
To: None <lib-bug-people@netbsd.org, gnats-admin@netbsd.org,>
From: Brian de Alwis <bsd@cs.ubc.ca>
List: netbsd-bugs
Date: 04/19/2007 21:45:00
>Number: 36175
>Category: lib
>Synopsis: mismatch of LANG and mutt's charset leads to excrutiatingly slow realloc(3) performance
>Confidential: no
>Severity: serious
>Priority: low
>Responsible: lib-bug-people
>State: open
>Class: sw-bug
>Submitter-Id: net
>Arrival-Date: Thu Apr 19 21:45:00 +0000 2007
>Originator: Brian de Alwis
>Release: NetBSD 4.99.17
>Organization:
Brian de Alwis | Software Practices Lab | UBC | http://www.cs.ubc.ca/~bsd/
"Amusement to an observing mind is study." - Benjamin Disraeli
>Environment:
System: NetBSD monolith 4.99.17 NetBSD 4.99.17 (LAPTOP.MP) #1: Tue Apr 17 23:13:03 CST 2007 bsd@monolith:/usr/obj/sys/arch/i386/compile/LAPTOP.MP i386
Architecture: i386
Machine: i386
>Description:
I'm seeing an excruciating slow-down using (an admittedly-misconfigured)
mutt when opening a mailbox with foreign characters. This situation
isn't likely to occur normally, but the behaviour is so puzzling
that there's likely a deeper issue. At best, this is some weirdness
to do with mutt; at worst, this may affect other apps (since mutt
uses the system iconv/libintl). I've suggested this as being
`serious', since it has quite an impact, but low priority as there
is a workaround.
I recently began reading my mail using mutt in a UTF-8 xterm.
I invoke mutt using:
xterm -u8 -e \
env LANG=en_CA.UTF-8 mutt -e 'set charset=utf-8; set ascii_chars'
which seems to do the right thing. I've been running like this
for a couple of weeks now.
I just today tried opening a mailbox that contains messages with
encoded names (see the uuencoded attachment) and found that mutt
appeared to hang. It turns out mutt doesn't actually hang, but
somehow gets into a situation where a memcpy(3) resulting from
realloc(3) causes an inordinate number of system page faults (see
below).
I've discovered that the high-level cause is that I'd forgotten to
remove an explicit charset command from my .muttrc which sets the
system charset to be `iso-8859-1', which conflicts with the LANG
setting of UTF-8. (mutt's charset code, in .../mutt/charset.c, seems
to do the right thing to converts the charset and provide it to
iconv.)
I should note that my machine had plenty of free memory (top reported
256M free), and the CPU is nice and peppy (a 2GHz Intel Core Duo).
I also just upgraded and rebuilt on -current as of Friday April
13. I mention this as I'm pretty sure I've previously looked at
the particular mail archive and not experienced this problem -- so
it may be related to some (somewhat) recent changes. I was previously
running a kernel and userland from 4.99.9.
>How-To-Repeat:
1. extract test-mailbox below
2. install pkgsrc/mail/mutt-devel with options `ncursesw smime ssl'
$ cd /usr/pkgsrc/mail/mutt-devel
$ make
(note: I have also verified this with the "ncursesw" package
option, which uses the wide-character ncurses, with the same
effect.)
3. run the following command:
$ LANG=en_US.UTF-8 \
work/mutt-1.15.14/mutt -n -e 'set charset=iso-8859-1' -f test-mailbox
4. see mutt appear to hang.
The conclusion drawn in step 4 isn't quite correct: mutt is actually
doing a memcpy but, for reasons that aren't quite clear to me, is
experiencing an intense slow-down doing a memcpy.
Attaching gdb (note: I recompiled mutt with a libc.so with debugging
symbols; it still hangs if I use the system libc.so, but it irealloc()
doesn't appear, and instead it looks like memcpy is called directly
by realloc):
(gdb) where
#0 0xbb9fea02 in irealloc (ptr=0x883a000, size=6504576)
at /usr/src/lib/libc/stdlib/malloc.c:865
#1 0xbb9ff500 in realloc (ptr=0x883a000, size=6504576)
at /usr/src/lib/libc/stdlib/malloc.c:1182
#2 0x080bc8fe in safe_realloc (ptr=0x81f3ec0, siz=6504576) at lib.c:174
#3 0x080c1457 in mutt_buffer_add (buf=0x81f3ec0, s=0xbfbfbba3 "�", len=3)
at muttlib.c:1605
#4 0x080c137b in mutt_buffer_addstr (buf=0x81f3ec0, s=0xbfbfbba3 "�")
at muttlib.c:1576
#5 0x080c226a in mutt_filter_unprintable (s=0xbfbfbc04) at mbyte.c:504
#6 0x080aabc1 in rfc2047_decode_word (
d=0x8169f00 "Re: explaining TOP memory output",
s=0x81f4dc0 "=?unknown-8bit?Q?Przemys=B3aw_Pawe=B3czyk?=", len=172)
at rfc2047.c:710
#7 0x080ab110 in rfc2047_decode (pd=0x81f3e20) at rfc2047.c:880
#8 0x080ab1cc in rfc2047_decode_adrlist (a=0x81f3e20) at rfc2047.c:900
#9 0x0809acb1 in mutt_read_rfc822_header (f=0xbba1c9c0, hdr=0x81f6380,
user_hdrs=0, weed=0) at parse.c:1432
#10 0x0808464e in mbox_parse_mailbox (ctx=0x8171500) at mbox.c:307
#11 0x08084b37 in mbox_open_mailbox (ctx=0x8171500) at mbox.c:432
#12 0x0808e4da in mx_open_mailbox (
path=0xbfbfe2d4 "/home/bsd/Mail/archive/netbsd", flags=0, pctx=0x0)
at mx.c:692
#13 0x08083c64 in main (argc=4, argv=0xbfbfe498) at main.c:982
This corresponds to the source:
(gdb) fr
#0 0xbb9fea02 in irealloc (ptr=0x883a000, size=6504576)
at /usr/src/lib/libc/stdlib/malloc.c:865
865 memcpy(p, ptr, osize);
(gdb) l
860 if (p != NULL) {
861 /* copy the lesser of the two sizes, and free the old one */
862 if (!size || !osize)
863 ;
864 else if (osize < size)
865 memcpy(p, ptr, osize);
866 else
867 memcpy(p, ptr, size);
868 ifree(ptr);
869 }
Disassembling the realloc code around 0xbb9fea02:
0xbb9fe9fa <irealloc+621>: mov 0xffffffe4(%ebp),%ecx
0xbb9fe9fd <irealloc+624>: mov %eax,%edi
0xbb9fe9ff <irealloc+626>: mov %edx,%esi
0xbb9fea01 <irealloc+628>: cld
0xbb9fea02 <irealloc+629>: repz movsb %ds:(%esi),%es:(%edi)
0xbb9fea04 <irealloc+631>: jmp 0xbb9fea16 <irealloc+649>
0xbb9fea06 <irealloc+633>: mov 0xffffffe0(%ebp),%eax
0xbb9fea09 <irealloc+636>: mov 0x8(%ebp),%edx
0xbb9fea0c <irealloc+639>: mov 0xc(%ebp),%ecx
So it's in the repz movsb, which corresponds to the memcpy.
And this memcpy takes ages. Looking at the registers:
(gdb) info reg
eax 0x81f7000 136278016
ecx 0x42810c 4358412
edx 0x883a000 142843904
ebx 0xbba10dbc -1147073092
esp 0xbfbfb980 0xbfbfb980
ebp 0xbfbfb9b8 0xbfbfb9b8
esi 0x8a45ef4 144989940
edi 0x8402ef4 138424052
eip 0xbb9fea02 0xbb9fea02
eflags 0x10383 66435
cs 0x17 23
ss 0x1f 31
ds 0x1f 31
es 0x1f 31
fs 0x0 0
gs 0x0 0
ecx is smaller that the size as I guess I interrupted it in the
loop. I can actually do a step, and it continues in the loop. I
decided to try doing a small number of iterations in the loop:
(gdb) stepi 484268
0xbb9fea02 865 memcpy(p, ptr, osize);
and ecx, esi, edi and changed accordingly. But this is *excruciatingly*
slow: these 484268 steps took over 2.5 minutes of wall-clock time.
At those speeds, this memcpy would take a total of 16 minutes!
Out of curiosity, I did a second stepi of 484268 instructions
(chosen as it was a tenth of the actual number of bytes being
copied, so I was sure it wouldn't complete early), while running
vmstat. The first and last two readings are from before and after
the stepi. You'll see the system faults increase.
$ vmstat 5
procs memory page disks faults cpu
r b w avm fre flt re pi po fr sr m0 c0 in sy cs us sy id
1 32 0 502636 263200 1791 0 0 0 0 0 0 0 676 8702 1919 9 4 86
1 32 0 502636 263200 6537 0 0 0 0 0 0 0 875 30010 6683 39 11 50
1 32 0 502636 263200 6456 0 0 0 0 0 0 0 1148 29651 6606 37 14 49
1 32 0 502636 263200 6574 0 0 0 0 0 0 0 691 30183 6722 41 9 50
1 32 0 502636 263200 6552 0 0 0 0 0 0 0 759 30081 6702 41 9 50
1 32 0 502636 263200 6493 0 0 0 0 0 0 0 1107 29807 6641 40 11 49
1 32 0 502636 263200 6473 0 0 0 0 0 0 0 1329 29718 6616 39 11 50
1 32 0 502636 263200 6529 0 0 0 0 0 0 0 977 29956 6671 41 9 50
1 32 0 502636 263200 6539 0 0 0 0 0 0 0 758 30030 6686 39 11 50
1 32 0 502636 263200 6531 0 0 0 0 0 0 0 947 29985 6677 40 11 49
2 31 0 502636 263200 6489 0 0 0 0 0 0 0 1287 29795 6635 39 11 50
3 32 0 502636 263200 6613 0 0 0 0 0 0 0 497 30338 6756 39 10 50
3 32 0 502636 263200 6591 0 0 0 0 0 0 0 621 30311 6748 42 11 48
2 32 0 502636 263200 6575 0 0 0 0 0 0 0 652 30169 6718 37 12 51
3 32 0 502636 263200 6507 0 0 0 0 0 0 0 870 29880 6657 38 11 51
1 32 0 502636 263200 6580 0 0 0 0 0 0 0 671 30205 6724 39 11 50
1 32 0 502636 263200 6581 0 0 0 0 0 0 0 644 30211 6729 38 12 50
1 32 0 502636 263200 6569 0 0 0 0 0 0 0 636 30151 6723 39 11 50
2 32 0 502636 263200 6504 0 0 0 0 0 0 0 1069 29863 6650 35 16 49
2 32 0 502636 263200 6561 0 0 0 0 0 0 0 805 30128 6709 37 14 49
3 32 0 502636 263200 6567 0 0 0 0 0 0 0 502 30148 6716 40 10 50
2 32 0 502636 263200 6555 0 0 0 0 0 0 0 813 30093 6703 38 13 49
1 32 0 502636 263200 6493 0 0 0 0 0 0 0 1246 29815 6634 38 13 49
1 32 0 502636 263200 6539 0 0 0 0 0 0 0 896 30013 6682 36 14 50
1 32 0 502636 263200 6545 0 0 0 0 0 0 0 873 30067 6693 35 15 50
1 31 0 502680 263168 6494 0 0 0 0 0 0 0 1055 29943 6656 36 15 50
1 31 0 502752 263124 6411 0 1 0 0 0 0 0 1445 29647 6582 37 14 49
4 30 0 502756 263124 6500 0 0 0 0 0 0 0 1131 29890 6653 36 15 49
1 32 0 502756 263124 6544 0 0 0 0 0 0 0 793 30079 6699 36 15 50
2 32 0 502756 263124 6557 0 0 0 0 0 0 0 791 30096 6701 38 12 50
0 32 0 502836 263044 2924 0 0 0 0 0 0 0 1334 13733 3023 19 8 73
2 32 0 502852 263028 29 0 0 0 0 0 0 0 1299 1185 214 1 4 95
I haven't been able to figure this out any further from this point.
I tried symlinking /etc/malloc.conf to `A', but it made no difference.
This is repeatable across reboots.
begin 644 test-mailbox
M1G)O;2!-04E,15(M1$%%34].(%1H=2!!<'(@(#4@,3(Z,SDZ-#<@,C`P,0I$
M871E.B`P-2!!<'(@,C`P,2`Q,CHS.3HT-R`M,#<P,`I&<F]M.B!-86EL(%-Y
M<W1E;2!);G1E<FYA;"!$871A(#Q-04E,15(M1$%%34].0&-S+G5B8RYC83X*
M4W5B:F5C=#H@1$].)U0@1$5,151%(%1(25,@34534T%'12`M+2!&3TQ$15(@
M24Y415).04P@1$%400I8+4E-05`Z(#`Y.#8T.3DU.#<@,#`P,#`P,#`P,`I3
M=&%T=7,Z(%)/"@I4:&ES('1E>'0@:7,@<&%R="!O9B!T:&4@:6YT97)N86P@
M9F]R;6%T(&]F('EO=7(@;6%I;"!F;VQD97(L(&%N9"!I<R!N;W0*82!R96%L
M(&UE<W-A9V4N("!)="!I<R!C<F5A=&5D(&%U=&]M871I8V%L;'D@8GD@=&AE
M(&UA:6P@<WES=&5M('-O9G1W87)E+@I)9B!D96QE=&5D+"!I;7!O<G1A;G0@
M9F]L9&5R(&1A=&$@=VEL;"!B92!L;W-T+"!A;F0@:70@=VEL;"!B92!R92UC
M<F5A=&5D"G=I=&@@=&AE(&1A=&$@<F5S970@=&\@:6YI=&EA;"!V86QU97,N
M"@I&<F]M(&-U<G)E;G0M=7-E<G,M;W=N97(M8G-D/6-S+G5B8RYC84!.971"
M4T0N;W)G("!7960@4V5P("`X(#$P.C(P.C0U(#(P,#0*4F5T=7)N+5!A=&@Z
M(#QC=7)R96YT+75S97)S+6]W;F5R+6)S9#UC<RYU8F,N8V%`3F5T0E-$+F]R
M9SX*4F5C96EV960Z("AF<F]M(&)S9$!L;V-A;&AO<W0I"@EB>2!B<V0N;&%P
M=&]P("@X+C$R+C$Q+S@N,3(N.2D@:60@:3@X2$M%6&<P,C8R-S0*"69O<B!B
M<V0[(%=E9"P@."!397`@,C`P-"`Q,#HR,#HQ-"`M,#<P,"`H4$14*0I296-E
M:79E9#H@9G)O;2!L;V-A;&AO<W0@6S$R-RXP+C`N,5T*"6)Y(&QO8V%L:&]S
M="!W:71H($E-05`@*&9E=&-H;6%I;"TV+C(N-2D*"69O<B!B<V1`;&]C86QH
M;W-T("AS:6YG;&4M9')O<"D[(%=E9"P@,#@@4V5P(#(P,#0@,3`Z,C`Z,30@
M+3`W,#`@*%!$5"D*4F5C96EV960Z(&9R;VT@8F%D96YP;W=E;&PN8W,N=6)C
M+F-A("AB861E;G!O=V5L;"YC<RYU8F,N8V$@6S$T,BXQ,#,N-BXW,5TI"@EB
M>2!P961I9W)E92YC<RYU8F,N8V$@*#@N,3(N,3`O."XQ,2XT*2!W:71H($53
M3510(&ED(&DX.$-T-$]Q,#`X.3$S"@EF;W(@/&)S9$!C<RYU8F,N8V$^.R!7
M960L(#@@4V5P(#(P,#0@,#4Z-34Z,#0@+3`W,#`@*%!$5"D*4F5C96EV960Z
M(&9R;VT@;6%I;"YN971B<V0N;W)G("AM86EL+FYE=&)S9"YO<F<@6S(P-"XQ
M-3(N,3DP+C$Q72D*"6)Y(&)A9&5N<&]W96QL+F-S+G5B8RYC82`H."XQ,BXX
M+S@N,3(N.2D@=VET:"!33510(&ED(&DX.$-T-&E5,#(V.3`S"@EF;W(@/&)S
M9$!C<RYU8F,N8V$^.R!7960L(#@@4V5P(#(P,#0@,#4Z-34Z,#0@+3`W,#`*
M4F5C96EV960Z("AQ;6%I;"`V.#DS(&EN=F]K960@8GD@=6ED(#8P-2D[(#@@
M4V5P(#(P,#0@,3(Z-30Z-#$@+3`P,#`*1&5L:79E<F5D+51O.B!C=7)R96YT
M+75S97)S0&YE=&)S9"YO<F<*4F5C96EV960Z("AQ;6%I;"`V.#<U(&EN=F]K
M960@9G)O;2!N971W;W)K*3L@."!397`@,C`P-"`Q,CHU-#HT,"`M,#`P,`I2
M96-E:79E9#H@9G)O;2!P;W)T+3(Q,BTR,#(M-#$M.2YD>6YA;6EC+G%S8RYD
M92`H2$5,3R!D<F5Y9G5S+F5S-#,M8FQN+FUA8V9I;FET>2YN970I("@R,3(N
M,C`R+C0Q+CDI"B`@8GD@;6%I;"YN971B<V0N;W)G('=I=&@@4TU44#L@."!3
M97`@,C`P-"`Q,CHU-#HT,"`M,#`P,`I296-E:79E9#H@9G)O;2!L;V-A;&AO
M<W0@*&QO8V%L:&]S="!;,3(W+C`N,"XQ72D*"6)Y(&1R97EF=7,N97,T,RUB
M;&XN;6%C9FEN:71Y+FYE="`H4&]S=&9I>"D@=VET:"!%4TU44"!I9"!#-S4U
M,C$Y,$)",3L*"5=E9"P@(#@@4V5P(#(P,#0@,30Z-3,Z-#0@*S`R,#`@*$-%
M4U0I"E)E8V5I=F5D.B!F<F]M(%LQ.3(N,38X+C$P,"XQ,C%=("AD<VPM,#@R
M+3`X,BTR,#,M,#,W+F%R8V]R+6EP+FYE="!;.#(N.#(N,C`S+C,W72D*"6)Y
M(&1R97EF=7,N97,T,RUB;&XN;6%C9FEN:71Y+FYE="`H4&]S=&9I>"D@=VET
M:"!%4TU44"!I9"`V1#`V.#$Y,$)",#L*"5=E9"P@(#@@4V5P(#(P,#0@,30Z
M-3,Z-#(@*S`R,#`@*$-%4U0I"DUI;64M5F5R<VEO;CH@,2XP("A!<'!L92!-
M97-S86=E(&9R86UE=V]R:R!V-C$Y*0I#;VYT96YT+51Y<&4Z('1E>'0O<&QA
M:6X[(&-H87)S970]55,M05-#24D[(&1E;'-P/7EE<SL@9F]R;6%T/69L;W=E
M9`I-97-S86=E+4ED.B`\,T(T.$5#-CDM,#$Y-BTQ,40Y+3A#1#,M,#`P-3`R
M-$0T,3(S0&UA8V9I;FET>2YN970^"D-O;G1E;G0M5')A;G-F97(M16YC;V1I
M;F<Z(#=B:70*1G)O;3H@/3])4T\M.#@U.2TQ/U$_5&EM;U]38V@]1C9L97(_
M/2`\=&EM;RYS8VAO96QE<D!M86-F:6YI='DN;F5T/@I3=6)J96-T.B!8+D]R
M9R!R96QE87-E<R`V+C@N,`I$871E.B!7960L(#@@4V5P(#(P,#0@,30Z-30Z
M,S,@*S`R,#`*5&\Z(")C=7)R96YT+75S97)S0&YE=&)S9"YO<F<@0W5R<F5N
M="(@/&-U<G)E;G0M=7-E<G-`3F5T0E-$+F]R9SX*6"U-86EL97(Z($%P<&QE
M($UA:6P@*#(N-C$Y*0I8+59I<G5S+5-C86YN960Z(&)Y("\O;6%C9FEN:71Y
M(%-W;W)D9FES:"!-86EL(%-E<G9E<@I396YD97(Z(&-U<G)E;G0M=7-E<G,M
M;W=N97)`3F5T0E-$+F]R9PI0<F5C961E;F-E.B!L:7-T"E@M1W)E>6QI<W0Z
M(%)E8VEP:65N="!E+6UA:6P@=VAI=&5L:7-T960L(&YO="!D96QA>65D(&)Y
M(&UI;'1E<BUG<F5Y;&ES="TQ+C0@*&)A9&5N<&]W96QL+F-S+G5B8RYC82!;
M,30R+C$P,RXV+C4R72D[(%=E9"P@,#@@4V5P(#(P,#0@,#4Z-34Z,#0@+3`W
M,#`@*%!$5"D*6"U3<&%M+5-C;W)E.B`Q+C8T-R!20U9$7TE.7TY*04),7T15
M3"Q20U9$7TE.7U-/4D)37T153`I8+5-C86YN960M0GDZ($U)345$969A;F<@
M,BXS-0I8+5-P86TM0VAE8VME<BU697)S:6]N.B!3<&%M07-S87-S:6X@,BXV
M,2`H,2XR,3(N,BXQ+3(P,#,M,3(M,#DM97AP*2!O;B!S;&%B"E@M4W!A;2U3
M=&%T=7,Z($YO+"!H:71S/3`N,"!R97%U:7)E9#TU+C`@=&5S=',]05=,(&%U
M=&]L96%R;CUH86T@=F5R<VEO;CTR+C8Q"E@M4W!A;2U,979E;#H@"E-T871U
M<SH@4D\*0V]N=&5N="U,96YG=&@Z(#0Q.`I,:6YE<SH@,30*"FAT='`Z+R]F
M<F5E9&5S:W1O<"YO<F<O?GAO<F<O6#$Q4C8N."XP+W-R8R\*"G)E860@;6]R
M92!H97)E.B`@"FAT='`Z+R]D979E;&]P97)S+G-L87-H9&]T+F]R9R]D979E
M;&]P97)S+S`T+S`Y+S`X+S$R-3(P."YS:'1M;#\@"G1I9#TQ,#0F=&ED/3$U
M,B9T:60].`H*+2T@"FUI="!V;W)Z=65G;&EC:'-T97(@2&]C:&%C:'1U;F<O
M8F5S="!R96=A<F1S+`H*5&EM;R!38VAO96QE<@HO+VUA8V9I;FET>2`M+2!F
M:6YE<W0@250@<V5R=FEC97,@?"!4<FEF='-T<F%S<V4@,SD@?"`Q,S,U,R!"
M97)L:6X@?"`@"D=E<FUA;GD*1F]N("LK-#D@,S`@,C4@,C`@,S`@,C`@?"!&
M87@@*RLT.2`S,"`R-2`R,"`S,"`Q.0I01U`@9&%T82!H='1P.B\O=W=W+FUA
M8V9I;FET>2YN970O?G1I<R]C;VYT86-T+U!'4%!+0E]T:6UO+G-C:&]E;&5R
&+G1X=`H*
`
end
>Fix:
--
Brian de Alwis | Software Practices Lab | UBC | http://www.cs.ubc.ca/~bsd/
"Amusement to an observing mind is study." - Benjamin Disraeli
>Unformatted:
Current to Friday April 13