Bug 152069

Summary: y2base and htdig take up an extreme amount of resources
Product: [openSUSE] SUSE Linux 10.1 Reporter: Joe Crollard <lunar_raven>
Component: YaST2Assignee: Jiri Srain <jsrain>
Status: RESOLVED FIXED QA Contact: Klaus Kämpf <kkaempf>
Severity: Enhancement    
Priority: P5 - None CC: dave, michel.munnix, mls, mrmazda, suse-beta
Version: Beta 4   
Target Milestone: ---   
Hardware: i686   
OS: Other   
Whiteboard:
Found By: Beta-Customer Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: /var/log/YaST2
y2log
durations for rpm and ldconfig executions
sample from y2log

Description Joe Crollard 2006-02-19 04:09:55 UTC
I installed suse 10.1 beta 4 today (coming from beta 3)..and noticed that on first boot it was very slow.  I then did a 'top'...and saw that htdig was taking about 60% of my memory.  Not exactly sure what that was..but I killed it and it went away.  

Then, I decided to check out yast.  Upon opening the new package manager, my system nearly came to a halt.  Total lag...and I could barely move the mouse pointer.  After finally opening a console, I did another 'top'.  Here is the results from that

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
30992 root      18   0  261m 162m 9124 D 10.0 65.5   0:37.72 y2base

As you can see, it's taking up a ton of memory, and does this the entire time the package manager window is open.

Hope this helps.
-Joe
Comment 1 Martin Lasarsch 2006-02-19 16:42:00 UTC
*** Bug 152066 has been marked as a duplicate of this bug. ***
Comment 2 Michael Gross 2006-02-20 12:00:50 UTC
Please attach the Yast logfiles in /var/log/YaST2/*
Raising to severity critical
Comment 3 Joe Crollard 2006-02-20 16:53:19 UTC
Created attachment 69368 [details]
/var/log/YaST2
Comment 4 Joe Crollard 2006-02-20 16:54:11 UTC
Comment on attachment 69368 [details]
/var/log/YaST2

Attached.  I wasnt sure which ones you needed, so I archived the /var/log/YaST2 directory.
Comment 5 michel munnix 2006-02-20 17:49:52 UTC
Same problem here, without htdig, while installing selections from cds:
top shows cpu waiting about 90% all the time.
yast2 uses 40% of the memory (256M on laptop).
ldconfig seems to be called very often, would'nt it suffice to run it at the very end? 
Comment 6 Michael Gross 2006-02-20 18:04:11 UTC
Joe: When in doubt always the whole directory.
I would say this is an issue with the packager.
Comment 8 Klaus Kämpf 2006-02-21 18:25:09 UTC
Hmm, are the logs taken while y2base is running (and consuming memory) ?

If not, please try to reproduce the behaviour and attach /var/log/YaST2/y2log
to this report.
Comment 9 Joe Crollard 2006-02-22 00:00:20 UTC
Created attachment 69666 [details]
y2log

Ok here is another log.   I took this during the 'reading package database' phase...and y2base was taking up about 69% of my memory (I am running a dell dimension desktop with 256 MB of RAM).  It seems that after that is complete, and the package manager is idle...it stops consuming so much memory.  However, if you I search for a package, or use the package manager in any way...the memory usage jumps right back up.
Comment 10 Klaus Kämpf 2006-02-27 11:03:10 UTC
Last line in log:
BinHeader.cc(string_val):307 RPM_TAG MISSMATCH: RPM_STRING_TYPE 1003 got type 4

Jiri, any idea ?
Comment 11 Jiri Srain 2006-02-27 20:53:09 UTC
No, no idea. The function which produces the last line in log obviously exits immediatelly after writing the message into the log.

Would it be possible to get the backtrace at the point of the problem?
Comment 12 Joe Crollard 2006-02-28 04:54:05 UTC
Well, I'm not exactly sure what was done, but the problem, atleast for me..no longer occurs in beta 5.
Comment 13 Jiri Srain 2006-02-28 16:12:08 UTC
OK, then I'm closing the bug as WORKSFORME. If you reproduce it in the future, please, attach the logs again and also add backtrace.
Comment 14 michel munnix 2006-03-01 08:26:47 UTC
same problem updating from beta4 to beta5 on IBM thinkpad R50 (256M RAM, 2G swap)
y2base size is VIRT:253M
I made a sample for 7:40 duration : 
30 rpms installed
ldconfig ran 8 times each time taking between 41 and 48 seconds

attaching log ps3 with following commands:

while true; do sleep 1; date >>ps2; ps -ef >>ps2; done
cat /proc/meminfo >ps3
grep ldconfig ps2 | cut -c10-20,48- | uniq -c >>ps3
grep rpm ps2 | cut -c10-20,48- | uniq -c >>ps3
Comment 15 michel munnix 2006-03-01 08:28:22 UTC
Created attachment 70728 [details]
durations for rpm and ldconfig executions
Comment 16 michel munnix 2006-03-01 09:19:47 UTC
I just calculated: 165 rpms with libs * 45 secconds = 2 hours extra installation time
Comment 17 Joe Crollard 2006-03-08 01:05:16 UTC
wow, if thats true that sounds bad.
Comment 18 michel munnix 2006-03-28 06:24:09 UTC
Same with update to beta8 (256M Ram 2G Swap Pentium M 1.5GHz), you have to expect 24 hours for the install.
The system is not swapping, but there is not much space for keeping a good file system cache in memory.
So "ldconfig" takes a very long time to run in between rpms and it is called very often.
Top shows the problem comes from y2base:
   virt:247M swap:88M res:159M data:199M shr:11M
If we could reduce the resident data size or only run ldconfig at the end of the installation, this could speedup the process.
Comment 19 Klaus Kämpf 2006-03-29 13:03:29 UTC
ldconfig runs ? I can hardly believe this.
Are you updating using YaST or rug ?
Comment 20 michel munnix 2006-03-29 14:32:41 UTC
I've made an update from beta6 to beta8, booting from CD1 and choosing to update the existing installation, so I think this is YaST.
After each rpm containing libraries, if I follow progress in y2log, I see that it waits until ldconfig is done.
I can see this in "top", where I see rpm and ldconfig running in sequence, the next rpm starts only after ldconfig terminates.
Here is an example of execution times:
2006-03-27 03:15:19    7s  /suse/i586/grep-2.5.1a-12.i586.rpm
2006-03-27 03:15:26    3s  /suse/i586/gzip-1.3.5-152.i586.rpm
2006-03-27 03:15:29    2s  /suse/i586/imlib2-loaders-1.2.1-10.i586.rpm
2006-03-27 03:15:31   88s  /suse/i586/libgcrypt-1.2.2-6.i586.rpm
2006-03-27 03:16:59   91s  /suse/i586/libidn-0.6.0-7.i586.rpm
2006-03-27 03:18:30   49s  /suse/i586/libmikmod-3.1.11-7.i586.rpm
2006-03-27 03:19:19   89s  /suse/i586/libsndfile-1.0.12-6.i586.rpm
2006-03-27 03:20:48

I have no idea if ldconfig is started by rpm or by yast, I'll attach the corresponding part of y2log
Comment 21 michel munnix 2006-03-29 14:34:05 UTC
Created attachment 75565 [details]
sample from y2log
Comment 22 michel munnix 2006-03-29 14:44:37 UTC
I just checked the ps2 file from my comment #14 
As you can see, it's rpm's fault :

root      1624  1545  0 08:08 tty1     00:00:00 /bin/sh /sbin/yast
root      2353     1  0 08:08 tty1     00:00:00 [gzip] <defunct>
root      2465  1624  0 08:08 tty1     00:00:00 /bin/sh /usr/lib/YaST2/startup/YaST2.call installation initial
root      2872  2465  3 08:08 tty7     00:00:43 X -deferglyphs 16 vt07
root      2882     1  0 08:08 tty1     00:00:00 fvwm2 -f /usr/X11R6/share/fvwm/fvwmrc.yast2
root      2891  2882  0 08:08 tty1     00:00:00 /usr/X11R6/lib/X11/fvwm2/FvwmCommandS 8 5 none 0 8
root      2926  2465  7 08:08 tty1     00:01:41 y2base installation ("initial") qt --fullscreen --noborder --auto-fonts
root      2953     1  0 08:08 tty1     00:00:00 [y2base] <defunct>
root      2971  2926  0 08:08 tty1     00:00:00 /bin/bash /usr/lib/YaST2/servers_non_y2/ag_fvwm2_setlang
root      3010     1  0 08:08 tty1     00:00:00 [gzip] <defunct>
root      3088     1  0 08:09 tty1     00:00:00 [y2base] <defunct>
root      3110     1  0 08:09 tty1     00:00:00 [y2base] <defunct>
root      3143     1  0 08:09 tty1     00:00:00 [y2base] <defunct>
root      3202     1  0 08:09 ?        00:00:00 [jfsIO]
root      3203     1  0 08:09 ?        00:00:00 [jfsCommit]
root      3204     1  0 08:09 ?        00:00:00 [jfsSync]
root      3210     6  0 08:09 ?        00:00:00 [xfslogd/0]
root      3211     6  0 08:09 ?        00:00:00 [xfsdatad/0]
root      3235     1  0 08:09 ?        00:00:00 [kjournald] <defunct>
root      3273     6  0 08:10 ?        00:00:00 [reiserfs/0]
root      3282     1  0 08:10 tty1     00:00:00 [gzip] <defunct>
root      3310     1  0 08:10 ?        00:00:00 [kjournald]
root      3405     6  0 08:15 ?        00:00:00 [pdflush]
root      3646  2926  4 08:31 tty1     00:00:00 rpm --root /mnt --dbpath /var/lib/rpm -U --percent -- /var/adm/mount/AP_0x00000001/suse/i586/utempter-0.5.5-7.i586.rpm
root      3650  3646  1 08:31 tty1     00:00:00 /sbin/ldconfig
root      3652  1536  0 08:31 tty2     00:00:00 ps -ef
Comment 23 Klaus Kämpf 2006-03-29 15:12:03 UTC
The y2log from comment #21 indeed shows that the time is spent in rpm:

2006-03-27 03:19:22 <0> linux(2916) [zypp] ExternalProgram.cc(start_program):166 Executing 'rpm' '--root' '/mnt' '--dbpath' '/var/lib/rpm' '-U' '--percent' '--' '/var/adm/mount/AP_0x00000001/suse/i586/libsndfile-1.0.12-6.i586.rpm'
2006-03-27 03:19:22 <0> linux(2916) [zypp] ExternalProgram.cc(start_program):276 pid 4081 launched
2006-03-27 03:20:48 <0> linux(2916) [zypp] ExternalProgram.cc(checkStatus):329 pid 4081 successfully completed

Almost looks like YAST_IS_RUNNING is not set (or not evaluated within rpm) ?!
Comment 24 Michael Schröder 2006-03-29 15:45:09 UTC
What do you mean? 'ldconfig' is (unfortunately) always run, and it always takes an insane amount of time. We had the same problem with 10.0. 
Comment 25 Klaus Kämpf 2006-03-29 16:39:37 UTC
Shouldn't it be postponed until the final SuSEconfig run ?
Comment 26 Michael Schröder 2006-03-29 17:56:57 UTC
I wish... unfortunately it can't as some postinstall scripts may need the new libraries.
Comment 27 David Herring 2006-04-06 16:45:39 UTC
I just installed SuSE 10.1 beta 9 on a compaq machine and see long y2base times (100% cpu y2base when accessing 'Software management'). I did an internet install using a local boot.iso cdrom.

Line from top is:-

5405 root      25   0 56552  29m  13m R  100  3.0   0:12.87 y2base

and a minute later still waiting for yast2 to respond...

5405 root      25   0 68976  42m  13m R  100  4.2   1:22.08 y2base

I beleive it's the time taken reading / processing the list of packages installed, as once yast2 as been running, going in and out of software management is quicker the second time. But if you stop yast2 then re-start it you get the same long delays on software management.

Comment 28 Stanislav Visnovsky 2006-04-06 21:27:53 UTC
Ad comment #27: this was always the case - the packages information is just huge.
Comment 29 michel munnix 2006-04-10 21:46:48 UTC
respective to comment #26: I tried the following
mv /sbin/ldconfig /sbin/ldconfig1
ln -s /bin/true /sbin/ldconfig
before starting the installation and repeated it before inserting CD2.
the gstreamer package was the first to be affected, so I ran ldconfig1 and retried the package. No more errors after that one.

what about: if post-install script fails, run real ldconfig and then retry package
Comment 30 Michael Schröder 2006-04-11 09:34:29 UTC
Ugh, no please. How about adding an incremental mode to ldconfig?
Comment 31 Jiri Srain 2006-04-14 21:25:31 UTC
Michael, is there anything we could do at all? Otherwise, I suggest marking this bug as WONTFIX as I don't see anything we could do to enhance the behavior...
Comment 32 Michael Schröder 2006-04-18 10:04:35 UTC
You could add an incremental mode to ldconfig... for 10.1/SLES10, nothing can be done.
Comment 33 Stanislav Visnovsky 2006-04-19 11:21:43 UTC
OK, marking as enhancement.
Comment 34 Jiri Srain 2006-08-08 14:22:49 UTC
Michael, can you provide some info about the incremental mode of ld config? What should be done on the YaST/ZYPP side, what should be done with each package...
Comment 35 Michael Schröder 2006-12-11 13:11:08 UTC
Uh, actually I've already implemented it in 10.2, didn't you notice? Closing this with FIXED.