Why is rpm -qa | grep openoffice.org2 soooo slow?

[Rodd Clarkson]

I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?

It eventually turns out some output, but it takes the better part of a
couple of minutes (very subjective, but I managed to talk to my wife
about something and then type this email and it still isn't finished, so
it's a reasonable amount of time.)  Actually a couple of minutes is
bloody generous.

After waiting so long i decided to do a real test, so here it is...

[rodd@localhost database]$ time rpm -qa | grep openoffice.org2
openoffice.org2-impress-1.9.77-1
openoffice.org2-core-1.9.77-1
openoffice.org2-xsltfilter-1.9.77-1
openoffice.org2-writer-1.9.77-1
openoffice.org2-graphicfilter-1.9.77-1

real    6m28.496s
user    0m3.070s
sys     0m0.559s
[rodd@localhost database]$

Rodd

[thomas cameron]

----- Original Message ----- 
From: "Rodd Clarkson" 
To: 
Sent: Tuesday, February 15, 2005 2:15 AM
Subject: Why is rpm -qa | grep openoffice.org2 soooo slow?
> I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?
>
> It eventually turns out some output, but it takes the better part of a
> couple of minutes (very subjective, but I managed to talk to my wife
> about something and then type this email and it still isn't finished, so
> it's a reasonable amount of time.)  Actually a couple of minutes is
> bloody generous.
>
> After waiting so long i decided to do a real test, so here it is...
>
> [rodd@localhost database]$ time rpm -qa | grep openoffice.org2
> openoffice.org2-impress-1.9.77-1
> openoffice.org2-core-1.9.77-1
> openoffice.org2-xsltfilter-1.9.77-1
> openoffice.org2-writer-1.9.77-1
> openoffice.org2-graphicfilter-1.9.77-1
>
> real    6m28.496s
> user    0m3.070s
> sys     0m0.559s
> [rodd@localhost database]$
>
> Rodd

What kind of system are you using?  What type of CPU?  Speed?  Amount of 
memory?  Type and speed of disk?

Thomas

[Rodd Clarkson]

> > Rodd
>
> What kind of system are you using?  What type of CPU?  Speed?  Amount of 
> memory?  Type and speed of disk?
>
> Thomas

All excellent questions that should have been answered before they were
asked.

System Type: x86 Laptop
Processor: P3-1GHz.
Memory: 512MB
Harddisk: 40GB, 5400RPM

RPM used to be much faster at this sort of thing.

Rodd

[thomas cameron]

On Tue, 2005-02-15 at 20:23 +1100, Rodd Clarkson wrote:
> > > Rodd
> >
> > What kind of system are you using?  What type of CPU?  Speed?  Amount of 
> > memory?  Type and speed of disk?
> >
> > Thomas
>
> All excellent questions that should have been answered before they were
> asked.
>
> System Type: x86 Laptop
> Processor: P3-1GHz.
> Memory: 512MB
> Harddisk: 40GB, 5400RPM
>
> RPM used to be much faster at this sort of thing.
>
> Rodd

"Used to be" before what?  Was there a change to the system?  What were
you running before?

I will admit that it sounds like there is something weird on your
laptop.  I don't have anything that old but it certainly seems like a 1
GHz processor with plenty of RAM should go faster than that.

Have you looked at setting the hdparm settings for your disk to speed it
up?  Have a look in /etc/sysconfig/harddisks for some settings you can
change to seriously speed up your IDE drive.

Past that, I would look at what if anything else is going on on your
machine while you run your command.

Thomas

[Rodd Clarkson]

On Tue, 2005-02-15 at 10:40 -0600, Thomas Cameron wrote:
> "Used to be" before what?  Was there a change to the system?  What were
> you running before?

I'm sure you've been watching other parts of this thread, but it turns
out is "used to be" before I upgraded to rpm-4.4

Rodd

[Panu Matilainen]

On Tue, 15 Feb 2005, Rodd Clarkson wrote:
> I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?
>
> It eventually turns out some output, but it takes the better part of a
> couple of minutes (very subjective, but I managed to talk to my wife
> about something and then type this email and it still isn't finished, so
> it's a reasonable amount of time.)  Actually a couple of minutes is
> bloody generous.
>
> After waiting so long i decided to do a real test, so here it is...
>
> [rodd@localhost database]$ time rpm -qa | grep openoffice.org2
> openoffice.org2-impress-1.9.77-1
> openoffice.org2-core-1.9.77-1
> openoffice.org2-xsltfilter-1.9.77-1
> openoffice.org2-writer-1.9.77-1
> openoffice.org2-graphicfilter-1.9.77-1
>
> real    6m28.496s
> user    0m3.070s
> sys     0m0.559s
> [rodd@localhost database]$

Well, that depends on the overall system speed, number of installed 
packages etc. A real killer for rpm query performance is the number of 
verifications rpm does by default - on my laptop:

time rpm -qa > /dev/null

real    0m5.131s
user    0m4.900s
sys     0m0.110s

...but disabling signature checks makes it go waaay faster:
time rpm -qa --nodigest --nosignature > /dev/null

real    0m0.513s
user    0m0.260s
sys     0m0.160s

- Panu -

[Michael Schwendt]

On Tue, 15 Feb 2005 19:15:46 +1100, Rodd Clarkson wrote:
> I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?
>
> It eventually turns out some output, but it takes the better part of a
> couple of minutes (very subjective, but I managed to talk to my wife
> about something and then type this email and it still isn't finished, so
> it's a reasonable amount of time.)  Actually a couple of minutes is
> bloody generous.
>
> After waiting so long i decided to do a real test, so here it is...
>
> [rodd@localhost database]$ time rpm -qa | grep openoffice.org2
> openoffice.org2-impress-1.9.77-1
> openoffice.org2-core-1.9.77-1
> openoffice.org2-xsltfilter-1.9.77-1
> openoffice.org2-writer-1.9.77-1
> openoffice.org2-graphicfilter-1.9.77-1
>
> real    6m28.496s
> user    0m3.070s
> sys     0m0.559s
> [rodd@localhost database]$

One thing for certain, that doesn't look normal. Your test shows that the
process took only roughly 3.6 seconds of CPU time. So it didn't compute a
lot. Under normal circumstances, it would have terminated after less than
four seconds. But possible it was interrupted very often or spent a lot of
time waiting for I/O or locks. Processes which sleep often (I doubt RPM
does that) would also increase the "real" execution time. Was your machine
very busy when you ran this test?

[Rodd Clarkson]

On Tue, 2005-02-15 at 10:44 +0100, Michael Schwendt wrote:
> > real    6m28.496s
> > user    0m3.070s
> > sys     0m0.559s
> > [rodd@localhost database]$
>
> One thing for certain, that doesn't look normal. Your test shows that the
> process took only roughly 3.6 seconds of CPU time. So it didn't compute a
> lot. Under normal circumstances, it would have terminated after less than
> four seconds. But possible it was interrupted very often or spent a lot of
> time waiting for I/O or locks. Processes which sleep often (I doubt RPM
> does that) would also increase the "real" execution time. Was your machine
> very busy when you ran this test?

Not that I'm aware of.  This isn't the first time I've seen this.  It's
been quite prevalent over the last few weeks(???).  I'm a little slack
with anything that's obvious because I figure (and rightly so most of
the time) that the developer knows and that they are doing something
about it.  If it's not addressed quickly, then I file a bug report
(after finding out if I'm a nut or not.)

I wasn't doing anything on the box at the time (no builds, no flash
movies, nothing I'm aware of).  the CPU indicator didn't suggest
anything was happening at the time (it was notably quite, which
surprised me I must admit)

Oh, and after setting the process running I went and got my 5 month old
out of the bath and dressed him for bed, so apart from a quick glance at
the screen, I wasn't doing any active work on the machine at the time.

Rodd

[Lars G]

Rodd Clarkson wrote:
> I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?
>
> It eventually turns out some output, but it takes the better part of a
> couple of minutes (very subjective, but I managed to talk to my wife
> about something and then type this email and it still isn't finished, so
> it's a reasonable amount of time.)  Actually a couple of minutes is
> bloody generous.
>
> After waiting so long i decided to do a real test, so here it is...
>
> [rodd@localhost database]$ time rpm -qa | grep openoffice.org2
> openoffice.org2-impress-1.9.77-1
> openoffice.org2-core-1.9.77-1
> openoffice.org2-xsltfilter-1.9.77-1
> openoffice.org2-writer-1.9.77-1
> openoffice.org2-graphicfilter-1.9.77-1
>
> real    6m28.496s
> user    0m3.070s
> sys     0m0.559s
> [rodd@localhost database]$
>
> Rodd

same here.
"rpm -qa" was a *lot* faster before on this system.
this is with latest rawhide and ooo2 (only writer & core installed)
on an nforce2 2.1ghz athlon xp with 1gig ram.

time rpm -qa | grep openoffice.org2
openoffice.org2-writer-1.9.77-1
openoffice.org2-core-1.9.77-1

real    1m51.435s
user    0m0.802s
sys     0m0.062s

really strange.

cheers
        lars

[Luciano Miguel Ferreira Rocha]

On Tue, Feb 15, 2005 at 07:15:46PM +1100, Rodd Clarkson wrote:
> [rodd@localhost database]$ time rpm -qa | grep openoffice.org2

And time sh -c 'rpm -qa | grep openoffice.org2'?

And time rpm -qa | fgrep openoffice.org2?

Regards,
Luciano Rocha

[Rodd Clarkson]

On Tue, 2005-02-15 at 10:41 +0000, Luciano Miguel Ferreira Rocha wrote:
> On Tue, Feb 15, 2005 at 07:15:46PM +1100, Rodd Clarkson wrote:
> > [rodd@localhost database]$ time rpm -qa | grep openoffice.org2
>
> And time sh -c 'rpm -qa | grep openoffice.org2'?
>
> And time rpm -qa | fgrep openoffice.org2?

We'll that 15 minutes of my life I'll never get back ;-]

[rodd@localhost ~]$ time sh -c 'rpm -qa | grep openoffice.org2'
openoffice.org2-impress-1.9.77-1
openoffice.org2-core-1.9.77-1
openoffice.org2-xsltfilter-1.9.77-1
openoffice.org2-writer-1.9.77-1
openoffice.org2-graphicfilter-1.9.77-1

real    6m35.301s
user    0m3.121s
sys     0m0.697s
[rodd@localhost ~]$ time rpm -qa | fgrep openoffice.org2
openoffice.org2-impress-1.9.77-1
openoffice.org2-core-1.9.77-1
openoffice.org2-xsltfilter-1.9.77-1
openoffice.org2-writer-1.9.77-1
openoffice.org2-graphicfilter-1.9.77-1

real    6m32.660s
user    0m3.097s
sys     0m0.615s
[rodd@localhost ~]$

Now, this is interesting.

If I just run 'time rpm -qa' then about 15 files appear and then this
file appears

gpg-pubkey-1cddbca9-3f9da14c

after this, the output stops for quite a while (with no real activity on
the CPU) then lots of output and then another stop after

gpg-pubkey-db42a60e-37ea5438
gpg-pubkey-30c9ecf8-3f9da3f7

quite a pause in proceeding, again with no notable CPU usage) and then
lots more files (the sort of output I would expect from rpm -qa) and
then it finishes.

The time info from this is:

real    6m41.756s
user    0m3.245s
sys     0m0.612s

so I think we can assume that the grep doesn't have anything to do with
this.

I suspect something is up with the files listed above.

Rodd

[Panu Matilainen]

On Tue, 15 Feb 2005, Rodd Clarkson wrote:
> Now, this is interesting.
>
> If I just run 'time rpm -qa' then about 15 files appear and then this
> file appears
>
> gpg-pubkey-1cddbca9-3f9da14c
>
> after this, the output stops for quite a while (with no real activity on
> the CPU) then lots of output and then another stop after
>
> gpg-pubkey-db42a60e-37ea5438
> gpg-pubkey-30c9ecf8-3f9da3f7
>
> quite a pause in proceeding, again with no notable CPU usage) and then
> lots more files (the sort of output I would expect from rpm -qa) and
> then it finishes.

Ahhah... This most likely has to do with rpm 4.4's automatic gpg key 
retrieval feature - I bet it's accessing network at that point and timing 
out because firewalls or such.

- Panu -

[Panu Matilainen]

On Tue, 15 Feb 2005, Panu Matilainen wrote:
> Ahhah... This most likely has to do with rpm 4.4's automatic gpg key 
> retrieval feature - I bet it's accessing network at that point and timing out 
> because firewalls or such.

Here's JBJ's original announcement about the feature, examples of the 
performance hit it causes and how to disable it:
https://lists.dulug.duke.edu/pipermail/rpm-devel/2004-November/000146.html

- Panu -

[Lars G]

Panu Matilainen wrote:
> On Tue, 15 Feb 2005, Panu Matilainen wrote:
> > Ahhah... This most likely has to do with rpm 4.4's automatic gpg key
> > retrieval feature - I bet it's accessing network at that point and timing
> > out because firewalls or such.
>
> Here's JBJ's original announcement about the feature, examples of the
> performance hit it causes and how to disable it:
> https://lists.dulug.duke.edu/pipermail/rpm-devel/2004-November/000146.html
> Panu -

thanks.
fired up ethereal, and it looks like its really getting gpg data from a
server named cryptonomicon.mit.edu.

best
        lars

[Lars G]

Lars wrote:
> Panu Matilainen wrote:
> > On Tue, 15 Feb 2005, Panu Matilainen wrote:
> > > Ahhah... This most likely has to do with rpm 4.4's automatic gpg key
> > > retrieval feature - I bet it's accessing network at that point and
> > > timing out because firewalls or such.
> >
> > Here's JBJ's original announcement about the feature, examples of the
> > performance hit it causes and how to disable it:

https://lists.dulug.duke.edu/pipermail/rpm-devel/2004-November/000146.html
> > Panu -
>
> thanks.
> fired up ethereal, and it looks like its really getting gpg data from a
> server named cryptonomicon.mit.edu.
>
> best
>         lars

imported a missing planetccrma gpg-key for the audio packages i had
installed, and no net-traffic anymore!

time rpm -qa | grep openoffice.org2
openoffice.org2-writer-1.9.77-1
openoffice.org2-core-1.9.77-1

real    0m0.984s
user    0m0.841s
sys     0m0.062s

btw. the auto gpg-key lookup in rpm is a really cool thing!

thanks!
        lars

[Paul Nasrat]

On Tue, Feb 15, 2005 at 07:15:46PM +1100, Rodd Clarkson wrote:
> I repeat... Why is rpm -qa | grep openoffice.org2 soooo slow?

Repeat the test with the following and report the times:

rpm -qa openoffice.org2*
rpm --nosignatures -qa | grep openoffice.org2

Create /etc/rpm/macros.test with the line:

%_hkp_keyserver %{unknown_macro}

Paul