What's taking so long??

What's taking so long??

[Gary Thomas]

My target platform/distro uses IPK and I have a local kernel
recipe which is based on the pre linux-yocto recipe that was
used by Poky.  When I build & package the kernel, I have
terrible performance - this is new, it used to be just fine.

Here's what I mean.  Building for my kernel and timing the
various steps, e.g.
   % time bitbake virtual/kernel -c compile

My kernel:
   compile            1m49s
   deploy             0m16s
   populate_sysroot   0m38s
   package           23m20s

Just to compare, using OTS Poky for BeagleBoard:
   compile            5m07s
   deploy             0m36s
   populate_sysroot   0m29s
   package            5m02s

That's a five-fold difference in the time to build & package
the kernel.

What am I doing [wrong?] that makes this so?
Would it be better if I switched to RPM like the BB is using?

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Joshua Lock]

On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
> My target platform/distro uses IPK and I have a local kernel
> recipe which is based on the pre linux-yocto recipe that was
> used by Poky.  When I build & package the kernel, I have
> terrible performance - this is new, it used to be just fine.
> 
> Here's what I mean.  Building for my kernel and timing the
> various steps, e.g.
>    % time bitbake virtual/kernel -c compile
> 
> My kernel:
>    compile            1m49s
>    deploy             0m16s
>    populate_sysroot   0m38s
>    package           23m20s
> 
> Just to compare, using OTS Poky for BeagleBoard:
>    compile            5m07s
>    deploy             0m36s
>    populate_sysroot   0m29s
>    package            5m02s
> 
> That's a five-fold difference in the time to build & package
> the kernel.

This is a significant performance impact. Thanks for taking the time to
do some profiling.

I've filed a bug http://bugzilla.pokylinux.org/show_bug.cgi?id=666 and
we'll get someone looking into that as a matter of priority.

> 
> What am I doing [wrong?] that makes this so?
> Would it be better if I switched to RPM like the BB is using?
> 

It looks like the slow paths are in package format independent code, so
probably not.

Regards,
Joshua
-- 
Joshua Lock
        Intel Open Source Technology Centre

Re: What's taking so long??

[Gary Thomas]

On 01/20/2011 08:58 AM, Joshua Lock wrote:
> On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
>> My target platform/distro uses IPK and I have a local kernel
>> recipe which is based on the pre linux-yocto recipe that was
>> used by Poky.  When I build&  package the kernel, I have
>> terrible performance - this is new, it used to be just fine.
>>
>> Here's what I mean.  Building for my kernel and timing the
>> various steps, e.g.
>>     % time bitbake virtual/kernel -c compile
>>
>> My kernel:
>>     compile            1m49s
>>     deploy             0m16s
>>     populate_sysroot   0m38s
>>     package           23m20s
>>
>> Just to compare, using OTS Poky for BeagleBoard:
>>     compile            5m07s
>>     deploy             0m36s
>>     populate_sysroot   0m29s
>>     package            5m02s
>>
>> That's a five-fold difference in the time to build&  package
>> the kernel.
>
> This is a significant performance impact. Thanks for taking the time to
> do some profiling.
>
> I've filed a bug http://bugzilla.pokylinux.org/show_bug.cgi?id=666 and
> we'll get someone looking into that as a matter of priority.
>
>>
>> What am I doing [wrong?] that makes this so?
>> Would it be better if I switched to RPM like the BB is using?
>>
>
> It looks like the slow paths are in package format independent code, so
> probably not.

Thanks.  I wonder what has changed as this used to be quite snappy!

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Koen Kooi]

Op 20 jan 2011, om 16:58 heeft Joshua Lock het volgende geschreven:

> On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
>> My target platform/distro uses IPK and I have a local kernel
>> recipe which is based on the pre linux-yocto recipe that was
>> used by Poky.  When I build & package the kernel, I have
>> terrible performance - this is new, it used to be just fine.
>> 
>> Here's what I mean.  Building for my kernel and timing the
>> various steps, e.g.
>>   % time bitbake virtual/kernel -c compile
>> 
>> My kernel:
>>   compile            1m49s
>>   deploy             0m16s
>>   populate_sysroot   0m38s
>>   package           23m20s
>> 
>> Just to compare, using OTS Poky for BeagleBoard:
>>   compile            5m07s
>>   deploy             0m36s
>>   populate_sysroot   0m29s
>>   package            5m02s
>> 
>> That's a five-fold difference in the time to build & package
>> the kernel.
> 
> This is a significant performance impact. Thanks for taking the time to
> do some profiling.
> 
> I've filed a bug http://bugzilla.pokylinux.org/show_bug.cgi?id=666 and
> we'll get someone looking into that as a matter of priority.
> 
>> 
>> What am I doing [wrong?] that makes this so?
>> Would it be better if I switched to RPM like the BB is using?
>> 
> 
> It looks like the slow paths are in package format independent code, so
> probably not.

From a chat I had with RP 2 weeks ago:

Koen: there's still something slow in bitbake log output
Koen: do_package takes eons (> 10mins) with almost zero IO and CPU
Koen: ctrl-c'ing it shows it's in the installed-but-not-packaged output
Richard Purdie: poky's bitbake or upstream?
Koen: I only tried poky bitbake so far
Koen: upstream is slow as well, but I don't recall being so slow
Koen: we talked about it at ELC
Richard Purdie: My memory isn't remembering that 
Richard Purdie: This is do_package for the kernel or something large?
Koen: kernel
Koen: but I think anything would trigger it
Koen: it feels like bitbake is only doing N lines of output per second
Koen: effectively throttling it
Koen: and with you have a 4k lines out output....
Richard Purdie: The message handling means thread context switching
Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
Richard Purdie: try changing the 0 for something like 100000
Richard Purdie: You won't get nice console output but it might run faster
Richard Purdie: Was poky running "faster" until recently?
Koen: I think so
Koen: I haven't measured it

Does doing:

Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
Richard Purdie: try changing the 0 for something like 100000

help?

regards,

Koen

Re: What's taking so long??

[Gary Thomas]

On 01/20/2011 09:04 AM, Koen Kooi wrote:
>
> Op 20 jan 2011, om 16:58 heeft Joshua Lock het volgende geschreven:
>
>> On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
>>> My target platform/distro uses IPK and I have a local kernel
>>> recipe which is based on the pre linux-yocto recipe that was
>>> used by Poky.  When I build&  package the kernel, I have
>>> terrible performance - this is new, it used to be just fine.
>>>
>>> Here's what I mean.  Building for my kernel and timing the
>>> various steps, e.g.
>>>    % time bitbake virtual/kernel -c compile
>>>
>>> My kernel:
>>>    compile            1m49s
>>>    deploy             0m16s
>>>    populate_sysroot   0m38s
>>>    package           23m20s
>>>
>>> Just to compare, using OTS Poky for BeagleBoard:
>>>    compile            5m07s
>>>    deploy             0m36s
>>>    populate_sysroot   0m29s
>>>    package            5m02s
>>>
>>> That's a five-fold difference in the time to build&  package
>>> the kernel.
>>
>> This is a significant performance impact. Thanks for taking the time to
>> do some profiling.
>>
>> I've filed a bug http://bugzilla.pokylinux.org/show_bug.cgi?id=666 and
>> we'll get someone looking into that as a matter of priority.
>>
>>>
>>> What am I doing [wrong?] that makes this so?
>>> Would it be better if I switched to RPM like the BB is using?
>>>
>>
>> It looks like the slow paths are in package format independent code, so
>> probably not.
>
>> From a chat I had with RP 2 weeks ago:
>
> Koen: there's still something slow in bitbake log output
> Koen: do_package takes eons (>  10mins) with almost zero IO and CPU
> Koen: ctrl-c'ing it shows it's in the installed-but-not-packaged output
> Richard Purdie: poky's bitbake or upstream?
> Koen: I only tried poky bitbake so far
> Koen: upstream is slow as well, but I don't recall being so slow
> Koen: we talked about it at ELC
> Richard Purdie: My memory isn't remembering that
> Richard Purdie: This is do_package for the kernel or something large?
> Koen: kernel
> Koen: but I think anything would trigger it
> Koen: it feels like bitbake is only doing N lines of output per second
> Koen: effectively throttling it
> Koen: and with you have a 4k lines out output....
> Richard Purdie: The message handling means thread context switching
> Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
> Richard Purdie: try changing the 0 for something like 100000
> Richard Purdie: You won't get nice console output but it might run faster
> Richard Purdie: Was poky running "faster" until recently?
> Koen: I think so
> Koen: I haven't measured it
>
> Does doing:
>
> Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
> Richard Purdie: try changing the 0 for something like 100000
>
> help?

No.

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Gary Thomas]

On 01/20/2011 09:34 AM, Gary Thomas wrote:
> On 01/20/2011 09:04 AM, Koen Kooi wrote:
>>
>> Op 20 jan 2011, om 16:58 heeft Joshua Lock het volgende geschreven:
>>
>>> On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
>>>> My target platform/distro uses IPK and I have a local kernel
>>>> recipe which is based on the pre linux-yocto recipe that was
>>>> used by Poky. When I build& package the kernel, I have
>>>> terrible performance - this is new, it used to be just fine.
>>>>
>>>> Here's what I mean. Building for my kernel and timing the
>>>> various steps, e.g.
>>>> % time bitbake virtual/kernel -c compile
>>>>
>>>> My kernel:
>>>> compile 1m49s
>>>> deploy 0m16s
>>>> populate_sysroot 0m38s
>>>> package 23m20s
>>>>
>>>> Just to compare, using OTS Poky for BeagleBoard:
>>>> compile 5m07s
>>>> deploy 0m36s
>>>> populate_sysroot 0m29s
>>>> package 5m02s
>>>>
>>>> That's a five-fold difference in the time to build& package
>>>> the kernel.
>>>
>>> This is a significant performance impact. Thanks for taking the time to
>>> do some profiling.
>>>
>>> I've filed a bug http://bugzilla.pokylinux.org/show_bug.cgi?id=666 and
>>> we'll get someone looking into that as a matter of priority.
>>>
>>>>
>>>> What am I doing [wrong?] that makes this so?
>>>> Would it be better if I switched to RPM like the BB is using?
>>>>
>>>
>>> It looks like the slow paths are in package format independent code, so
>>> probably not.
>>
>>> From a chat I had with RP 2 weeks ago:
>>
>> Koen: there's still something slow in bitbake log output
>> Koen: do_package takes eons (> 10mins) with almost zero IO and CPU
>> Koen: ctrl-c'ing it shows it's in the installed-but-not-packaged output
>> Richard Purdie: poky's bitbake or upstream?
>> Koen: I only tried poky bitbake so far
>> Koen: upstream is slow as well, but I don't recall being so slow
>> Koen: we talked about it at ELC
>> Richard Purdie: My memory isn't remembering that
>> Richard Purdie: This is do_package for the kernel or something large?
>> Koen: kernel
>> Koen: but I think anything would trigger it
>> Koen: it feels like bitbake is only doing N lines of output per second
>> Koen: effectively throttling it
>> Koen: and with you have a 4k lines out output....
>> Richard Purdie: The message handling means thread context switching
>> Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
>> Richard Purdie: try changing the 0 for something like 100000
>> Richard Purdie: You won't get nice console output but it might run faster
>> Richard Purdie: Was poky running "faster" until recently?
>> Koen: I think so
>> Koen: I haven't measured it
>>
>> Does doing:
>>
>> Richard Purdie: in runqueue.py there is a number 4096 and a 0 on the line below
>> Richard Purdie: try changing the 0 for something like 100000
>>
>> help?
>
> No.
>

Note: I got tired of waiting for this (I needed to rebuild
anyway) and typed ^C.  I got this dump which I don't understand:

NOTE: Sending SIGTERM to remaining 1 tasks
Warning, worker left partial message: <event>(ilogging
LogRecord
p1
(dp2
S'taskpid'
p3
I23606
sS'threadName'
p4
S'MainThread'
p5
sS'name'
p6
S'BitBake'
p7
sS'thread'
p8
I-1216357584
sS'created'
p9
F1295541481.8053031
sS'process'
p10
I23606
sS'processName'
p11
S'MainProcess'
p12
sS'args'
p13
(tsS'module'
p14
S'__init__'
p15
sS'filename'
p16
S'__init__.py'
p17
sS'levelno'
p18
I20
sS'exc_text'
p19
NsS'pathname'
p20
S'/home/local/poky-amltd/bitbake/lib/bb/__init__.py'
p21
sS'lineno'
p22
I85
sS'msg'
p23
S'  /kernel/arch/arm/plat-s3c64xx/dev-audio.c'
p24
sS'exc_info'
p25
NsS'funcName'
p26
S'note'
p27

What does it mean?  Maybe it helps understand the problem.

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Richard Purdie]

On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
> My target platform/distro uses IPK and I have a local kernel
> recipe which is based on the pre linux-yocto recipe that was
> used by Poky.  When I build & package the kernel, I have
> terrible performance - this is new, it used to be just fine.
> 
> Here's what I mean.  Building for my kernel and timing the
> various steps, e.g.
>    % time bitbake virtual/kernel -c compile
> 
> My kernel:
>    compile            1m49s
>    deploy             0m16s
>    populate_sysroot   0m38s
>    package           23m20s
> 
> Just to compare, using OTS Poky for BeagleBoard:
>    compile            5m07s
>    deploy             0m36s
>    populate_sysroot   0m29s
>    package            5m02s
> 
> That's a five-fold difference in the time to build & package
> the kernel.

This is a serious and worrying number. I just tried a test where I ran:

bitbake virtual/kernel -c package | ../predate.sh 

where predate.sh contains:

#!/bin/bash
while read line ; do
    echo "$(date): ${line}"
done

and I added a bb.error to the package functions interation loop in
package.bbclass.

I saw:

Fri Jan 21 13:58:00 GMT 2011: NOTE: Running task 667 of 667 (ID: 14, /media/build2/builds/rptest/meta/recipes-kernel/linux/linux-yocto_git.bb, do_package)
Fri Jan 21 13:58:00 GMT 2011: NOTE: package linux-yocto-2.6.37+git0+e3895db37bd65ea97e59b70ea936c84b398d3f3e_0+a9d833fda90e2f1257888a97e092135610b5f259-r15: task do_package: Started
Fri Jan 21 13:58:00 GMT 2011: ERROR: Running perform_packagecopy
Fri Jan 21 13:58:02 GMT 2011: ERROR: Running package_do_split_locales
Fri Jan 21 13:58:02 GMT 2011: ERROR: Running populate_packages
Fri Jan 21 13:58:02 GMT 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
Fri Jan 21 13:58:02 GMT 2011: 
Fri Jan 21 13:58:18 GMT 2011: ERROR: Running package_do_filedeps
Fri Jan 21 13:59:08 GMT 2011: ERROR: Running package_do_shlibs
Fri Jan 21 13:59:10 GMT 2011: ERROR: Running package_do_pkgconfig
Fri Jan 21 13:59:10 GMT 2011: ERROR: Running read_shlibdeps
Fri Jan 21 13:59:11 GMT 2011: ERROR: Running package_depchains
Fri Jan 21 13:59:11 GMT 2011: ERROR: Running emit_pkgdata
Fri Jan 21 13:59:11 GMT 2011: ERROR: Running do_package_qa
Fri Jan 21 14:00:42 GMT 2011: NOTE: package linux-yocto-2.6.37+git0+e3895db37bd65ea97e59b70ea936c84b398d3f3e_0+a9d833fda90e2f1257888a97e092135610b5f259-r15: task do_package: Succeeded
Fri Jan 21 14:00:42 GMT 2011: NOTE: Tasks Summary: Attempted 667 tasks of which 615 didn't need to be rerun and 0 failed.

so it did this in 2.6 minutes which doesn't seem unreasonable.

Are you seeing the slow package step in current master and when you made
the timings above, were they the only task running or were there others
active too?

Cheers,

Richard

Re: What's taking so long??

[Richard Purdie]

On Thu, 2011-01-20 at 09:40 -0700, Gary Thomas wrote:
> Note: I got tired of waiting for this (I needed to rebuild
> anyway) and typed ^C.  I got this dump which I don't understand:
> 
> NOTE: Sending SIGTERM to remaining 1 tasks
> Warning, worker left partial message: <event>(ilogging
> LogRecord
> p1
> (dp2
> S'taskpid'
> p3
> I23606
> sS'threadName'
> p4
> S'MainThread'
> p5
> sS'name'
> p6
> S'BitBake'
> p7
> sS'thread'
> p8
> I-1216357584
> sS'created'
> p9
> F1295541481.8053031
> sS'process'
> p10
> I23606
> sS'processName'
> p11
> S'MainProcess'
> p12
> sS'args'
> p13
> (tsS'module'
> p14
> S'__init__'
> p15
> sS'filename'
> p16
> S'__init__.py'
> p17
> sS'levelno'
> p18
> I20
> sS'exc_text'
> p19
> NsS'pathname'
> p20
> S'/home/local/poky-amltd/bitbake/lib/bb/__init__.py'
> p21
> sS'lineno'
> p22
> I85
> sS'msg'
> p23
> S'  /kernel/arch/arm/plat-s3c64xx/dev-audio.c'
> p24
> sS'exc_info'
> p25
> NsS'funcName'
> p26
> S'note'
> p27
> 
> What does it mean?  Maybe it helps understand the problem.

Its the internal representation of what you see as messages on the
bitbake console (output of a pickled LogRecord). The worker didn't
complete its queue so there was a partial message, it doesn't help work
out where the time is being spent sadly.

Cheers,

Richard

Re: What's taking so long??

[Gary Thomas]

On 01/21/2011 07:10 AM, Richard Purdie wrote:
> On Thu, 2011-01-20 at 08:11 -0700, Gary Thomas wrote:
>> My target platform/distro uses IPK and I have a local kernel
>> recipe which is based on the pre linux-yocto recipe that was
>> used by Poky.  When I build&  package the kernel, I have
>> terrible performance - this is new, it used to be just fine.
>>
>> Here's what I mean.  Building for my kernel and timing the
>> various steps, e.g.
>>     % time bitbake virtual/kernel -c compile
>>
>> My kernel:
>>     compile            1m49s
>>     deploy             0m16s
>>     populate_sysroot   0m38s
>>     package           23m20s
>>
>> Just to compare, using OTS Poky for BeagleBoard:
>>     compile            5m07s
>>     deploy             0m36s
>>     populate_sysroot   0m29s
>>     package            5m02s
>>
>> That's a five-fold difference in the time to build&  package
>> the kernel.
>
> This is a serious and worrying number. I just tried a test where I ran:
>
> bitbake virtual/kernel -c package | ../predate.sh
>
> where predate.sh contains:
>
> #!/bin/bash
> while read line ; do
>      echo "$(date): ${line}"
> done
>
> and I added a bb.error to the package functions interation loop in
> package.bbclass.
>
> I saw:
>
> Fri Jan 21 13:58:00 GMT 2011: NOTE: Running task 667 of 667 (ID: 14, /media/build2/builds/rptest/meta/recipes-kernel/linux/linux-yocto_git.bb, do_package)
> Fri Jan 21 13:58:00 GMT 2011: NOTE: package linux-yocto-2.6.37+git0+e3895db37bd65ea97e59b70ea936c84b398d3f3e_0+a9d833fda90e2f1257888a97e092135610b5f259-r15: task do_package: Started
> Fri Jan 21 13:58:00 GMT 2011: ERROR: Running perform_packagecopy
> Fri Jan 21 13:58:02 GMT 2011: ERROR: Running package_do_split_locales
> Fri Jan 21 13:58:02 GMT 2011: ERROR: Running populate_packages
> Fri Jan 21 13:58:02 GMT 2011: WARNING:<string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
> Fri Jan 21 13:58:02 GMT 2011:
> Fri Jan 21 13:58:18 GMT 2011: ERROR: Running package_do_filedeps
> Fri Jan 21 13:59:08 GMT 2011: ERROR: Running package_do_shlibs
> Fri Jan 21 13:59:10 GMT 2011: ERROR: Running package_do_pkgconfig
> Fri Jan 21 13:59:10 GMT 2011: ERROR: Running read_shlibdeps
> Fri Jan 21 13:59:11 GMT 2011: ERROR: Running package_depchains
> Fri Jan 21 13:59:11 GMT 2011: ERROR: Running emit_pkgdata
> Fri Jan 21 13:59:11 GMT 2011: ERROR: Running do_package_qa
> Fri Jan 21 14:00:42 GMT 2011: NOTE: package linux-yocto-2.6.37+git0+e3895db37bd65ea97e59b70ea936c84b398d3f3e_0+a9d833fda90e2f1257888a97e092135610b5f259-r15: task do_package: Succeeded
> Fri Jan 21 14:00:42 GMT 2011: NOTE: Tasks Summary: Attempted 667 tasks of which 615 didn't need to be rerun and 0 failed.
>
> so it did this in 2.6 minutes which doesn't seem unreasonable.
>
> Are you seeing the slow package step in current master and when you made
> the timings above, were they the only task running or were there others
> active too?

This particular test was isolated, just that one recipe.  I noticed
it before when building a complete image, so running it isolated does not
seem to make any difference.  There is also nothing else running on my build
machine (it's a separate server that is used only for builds)

This is against master as of 2011-01-14 (897530621fabf3c345c302050a5c21e16097a2ba)
with my local layers.

What can I look at (alternatively what data can I provide) to help
understand this?

Thanks


-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Richard Purdie]

On Fri, 2011-01-21 at 07:25 -0700, Gary Thomas wrote:
> This particular test was isolated, just that one recipe.  I noticed
> it before when building a complete image, so running it isolated does not
> seem to make any difference.  There is also nothing else running on my build
> machine (it's a separate server that is used only for builds)
> 
> This is against master as of 2011-01-14 (897530621fabf3c345c302050a5c21e16097a2ba)
> with my local layers.
> 
> What can I look at (alternatively what data can I provide) to help
> understand this?

You could try pulling in:
http://git.pokylinux.org/cgit.cgi/poky/commit/?id=ede381d56b180b384fdad98d445e5430819cfade
http://git.pokylinux.org/cgit.cgi/poky/commit/?id=7857834691868b7f48f732ee78d8770f5473ff68
http://git.pokylinux.org/cgit.cgi/poky/commit/?id=fd88588df029604689db9b0e30c55aad68392a5d

and see if they fix the problem. I'm not sure that they would in a
single task case but who knows. You could also try adding timings as per
my previous email, the change to package.bbclass was simply:

diff --git a/meta/classes/package.bbclass b/meta/classes/package.bbclass
index 8e7fa26..8b0cb96 100644
--- a/meta/classes/package.bbclass
+++ b/meta/classes/package.bbclass
@@ -1082,6 +1082,7 @@ python package_do_package () {
                return
 
        for f in (bb.data.getVar('PACKAGEFUNCS', d, True) or '').split():
+               bb.error("Running %s" % f)
                bb.build.exec_func(f, d)
 }
 do_package[dirs] = "${SHLIBSWORKDIR} ${PKGDESTWORK} ${D}"

as I'd like to understand of the 23 minutes, where the time is being spent.

Cheers,

Richard

Re: What's taking so long??

[Gary Thomas]

On 01/21/2011 09:17 AM, Richard Purdie wrote:
> On Fri, 2011-01-21 at 07:25 -0700, Gary Thomas wrote:
>> This particular test was isolated, just that one recipe.  I noticed
>> it before when building a complete image, so running it isolated does not
>> seem to make any difference.  There is also nothing else running on my build
>> machine (it's a separate server that is used only for builds)
>>
>> This is against master as of 2011-01-14 (897530621fabf3c345c302050a5c21e16097a2ba)
>> with my local layers.
>>
>> What can I look at (alternatively what data can I provide) to help
>> understand this?
>
> You could try pulling in:
> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=ede381d56b180b384fdad98d445e5430819cfade
> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=7857834691868b7f48f732ee78d8770f5473ff68
> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=fd88588df029604689db9b0e30c55aad68392a5d
>
> and see if they fix the problem. I'm not sure that they would in a
> single task case but who knows. You could also try adding timings as per
> my previous email, the change to package.bbclass was simply:
>
> diff --git a/meta/classes/package.bbclass b/meta/classes/package.bbclass
> index 8e7fa26..8b0cb96 100644
> --- a/meta/classes/package.bbclass
> +++ b/meta/classes/package.bbclass
> @@ -1082,6 +1082,7 @@ python package_do_package () {
>                  return
>
>          for f in (bb.data.getVar('PACKAGEFUNCS', d, True) or '').split():
> +               bb.error("Running %s" % f)
>                  bb.build.exec_func(f, d)
>   }
>   do_package[dirs] = "${SHLIBSWORKDIR} ${PKGDESTWORK} ${D}"
>
> as I'd like to understand of the 23 minutes, where the time is being spent.

For my board:
Fri Jan 21 10:12:13 MST 2011: NOTE: Running task 658 of 661 (ID: 11, /home/local/poky-amltd/meta-amltd/packages/linux/linux-am_2.6.32.bb, do_package)
Fri Jan 21 10:12:13 MST 2011: NOTE: package linux-am-2.6.32-r0: task do_package: Started
Fri Jan 21 10:12:13 MST 2011: ERROR: Running perform_packagecopy
Fri Jan 21 10:12:27 MST 2011: ERROR: Running package_do_split_locales
Fri Jan 21 10:12:27 MST 2011: ERROR: Running populate_packages
Fri Jan 21 10:12:27 MST 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
Fri Jan 21 10:12:27 MST 2011:
Fri Jan 21 10:12:45 MST 2011: NOTE: package linux-am-2.6.32-r0: task do_populate_sysroot: Succeeded
Fri Jan 21 10:28:33 MST 2011: ERROR: Running package_do_filedeps
Fri Jan 21 10:34:16 MST 2011: ERROR: Running package_do_shlibs
Fri Jan 21 10:34:21 MST 2011: ERROR: Running package_do_pkgconfig
Fri Jan 21 10:34:23 MST 2011: ERROR: Running read_shlibdeps
Fri Jan 21 10:34:23 MST 2011: ERROR: Running package_depchains
Fri Jan 21 10:34:23 MST 2011: ERROR: Running emit_pkgdata
Fri Jan 21 10:34:23 MST 2011: ERROR: Running do_package_qa

For the BeagleBoard:
Fri Jan 21 13:32:22 MST 2011: NOTE: Running task 878 of 882 (ID: 17, /home/local/poky-amltd/meta/recipes-kernel/linux/linux-yocto-stable_git.bb, do_package)
Fri Jan 21 13:32:22 MST 2011: NOTE: package linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1: task do_package: 
Started
Fri Jan 21 13:32:23 MST 2011: ERROR: Running perform_packagecopy
Fri Jan 21 13:32:25 MST 2011: ERROR: Running package_do_split_locales
Fri Jan 21 13:32:26 MST 2011: ERROR: Running populate_packages
Fri Jan 21 13:32:27 MST 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
Fri Jan 21 13:32:27 MST 2011:
Fri Jan 21 13:32:31 MST 2011: NOTE: package linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1: task 
do_populate_sysroot: Succeeded
Fri Jan 21 13:32:43 MST 2011: ERROR: Running package_do_filedeps
Fri Jan 21 13:35:52 MST 2011: ERROR: Running package_do_shlibs
Fri Jan 21 13:35:54 MST 2011: ERROR: Running package_do_pkgconfig
Fri Jan 21 13:35:54 MST 2011: ERROR: Running read_shlibdeps
Fri Jan 21 13:35:55 MST 2011: ERROR: Running package_depchains
Fri Jan 21 13:35:55 MST 2011: ERROR: Running emit_pkgdata
Fri Jan 21 13:35:55 MST 2011: ERROR: Running do_package_qa

Interesting results.  I'm going to run it again, with more messages
in the two time consuming steps - populate_packages & package_do_filedeps

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

Re: What's taking so long??

[Gary Thomas]

[-- Attachment #1: Type: text/plain, Size: 10855 bytes --]

On 01/21/2011 01:48 PM, Gary Thomas wrote:
> On 01/21/2011 09:17 AM, Richard Purdie wrote:
>> On Fri, 2011-01-21 at 07:25 -0700, Gary Thomas wrote:
>>> This particular test was isolated, just that one recipe. I noticed
>>> it before when building a complete image, so running it isolated does not
>>> seem to make any difference. There is also nothing else running on my build
>>> machine (it's a separate server that is used only for builds)
>>>
>>> This is against master as of 2011-01-14 (897530621fabf3c345c302050a5c21e16097a2ba)
>>> with my local layers.
>>>
>>> What can I look at (alternatively what data can I provide) to help
>>> understand this?
>>
>> You could try pulling in:
>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=ede381d56b180b384fdad98d445e5430819cfade
>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=7857834691868b7f48f732ee78d8770f5473ff68
>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=fd88588df029604689db9b0e30c55aad68392a5d
>>
>> and see if they fix the problem. I'm not sure that they would in a
>> single task case but who knows. You could also try adding timings as per
>> my previous email, the change to package.bbclass was simply:
>>
>> diff --git a/meta/classes/package.bbclass b/meta/classes/package.bbclass
>> index 8e7fa26..8b0cb96 100644
>> --- a/meta/classes/package.bbclass
>> +++ b/meta/classes/package.bbclass
>> @@ -1082,6 +1082,7 @@ python package_do_package () {
>> return
>>
>> for f in (bb.data.getVar('PACKAGEFUNCS', d, True) or '').split():
>> + bb.error("Running %s" % f)
>> bb.build.exec_func(f, d)
>> }
>> do_package[dirs] = "${SHLIBSWORKDIR} ${PKGDESTWORK} ${D}"
>>
>> as I'd like to understand of the 23 minutes, where the time is being spent.
>
> For my board:
> Fri Jan 21 10:12:13 MST 2011: NOTE: Running task 658 of 661 (ID: 11, /home/local/poky-amltd/meta-amltd/packages/linux/linux-am_2.6.32.bb, do_package)
> Fri Jan 21 10:12:13 MST 2011: NOTE: package linux-am-2.6.32-r0: task do_package: Started
> Fri Jan 21 10:12:13 MST 2011: ERROR: Running perform_packagecopy
> Fri Jan 21 10:12:27 MST 2011: ERROR: Running package_do_split_locales
> Fri Jan 21 10:12:27 MST 2011: ERROR: Running populate_packages
> Fri Jan 21 10:12:27 MST 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
> Fri Jan 21 10:12:27 MST 2011:
> Fri Jan 21 10:12:45 MST 2011: NOTE: package linux-am-2.6.32-r0: task do_populate_sysroot: Succeeded
> Fri Jan 21 10:28:33 MST 2011: ERROR: Running package_do_filedeps
> Fri Jan 21 10:34:16 MST 2011: ERROR: Running package_do_shlibs
> Fri Jan 21 10:34:21 MST 2011: ERROR: Running package_do_pkgconfig
> Fri Jan 21 10:34:23 MST 2011: ERROR: Running read_shlibdeps
> Fri Jan 21 10:34:23 MST 2011: ERROR: Running package_depchains
> Fri Jan 21 10:34:23 MST 2011: ERROR: Running emit_pkgdata
> Fri Jan 21 10:34:23 MST 2011: ERROR: Running do_package_qa
>
> For the BeagleBoard:
> Fri Jan 21 13:32:22 MST 2011: NOTE: Running task 878 of 882 (ID: 17, /home/local/poky-amltd/meta/recipes-kernel/linux/linux-yocto-stable_git.bb, do_package)
> Fri Jan 21 13:32:22 MST 2011: NOTE: package linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1: task do_package:
> Started
> Fri Jan 21 13:32:23 MST 2011: ERROR: Running perform_packagecopy
> Fri Jan 21 13:32:25 MST 2011: ERROR: Running package_do_split_locales
> Fri Jan 21 13:32:26 MST 2011: ERROR: Running populate_packages
> Fri Jan 21 13:32:27 MST 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security risk to your program
> Fri Jan 21 13:32:27 MST 2011:
> Fri Jan 21 13:32:31 MST 2011: NOTE: package linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1: task
> do_populate_sysroot: Succeeded
> Fri Jan 21 13:32:43 MST 2011: ERROR: Running package_do_filedeps
> Fri Jan 21 13:35:52 MST 2011: ERROR: Running package_do_shlibs
> Fri Jan 21 13:35:54 MST 2011: ERROR: Running package_do_pkgconfig
> Fri Jan 21 13:35:54 MST 2011: ERROR: Running read_shlibdeps
> Fri Jan 21 13:35:55 MST 2011: ERROR: Running package_depchains
> Fri Jan 21 13:35:55 MST 2011: ERROR: Running emit_pkgdata
> Fri Jan 21 13:35:55 MST 2011: ERROR: Running do_package_qa
>
> Interesting results. I'm going to run it again, with more messages
> in the two time consuming steps - populate_packages & package_do_filedeps
>

I've isolated it down to this section of code in 'populate_packages':

	unshipped = []
	for root, dirs, files in os.walk(dvar):	
		for f in files:
			path = os.path.join(root[len(dvar):], f)
			if ('.' + path) not in seen:
				unshipped.append(path)

	if unshipped != []:
		bb.note("the following files were installed but not shipped in any package:")
		for f in unshipped:		
			bb.note("  " + f)

The difference comes from what's in that ".../package" tree.
For my kernel:
   $ find /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/package | wc
      8567    8567 1098403
For the OTS BeagleBoard kernel:
   $ find 
/home/local/bb_poky/tmp/work/beagleboard-poky-linux-gnueabi/linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1/package 
| wc
      1598    1598  364151

I measured this and in the 'for f in unshipped:' loop above, each
iteration is taking ~125ms!  I have a hard time understanding why,
but 8567*125ms = 1070.875sec = 17.847min!

I also found that later on, in 'do_filedeps()', some packages take
an extraordinary amount of time.  Looking at a few:
Sat Jan 22 09:17:55 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-image
Sat Jan 22 09:17:55 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-image
Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-dev
Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-dev
Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-vmlinux
Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-vmlinux
Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-misc
Sat Jan 22 09:20:36 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-misc
Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-crc-itu-t
Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-crc-itu-t
Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --provides 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-g-cdc
Sat Jan 22 09:23:29 MST 2011: ERROR: do_filedeps: /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh --rpmdeps 
/home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps --requires 
/home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-g-cdc

You'll see that most take a few seconds (at most), but the 'kernel-misc'
package is taking 6 minutes by itself!  This particular sub-package seems
to be completely different between the two kernels.
Mine:
-rwxrw-r-- 1 gthomas gthomas  8627800 Jan 22 09:25 tmp/deploy/ipk/cobra3530p60/kernel-misc_2.6.32-r0_cobra3530p60.ipk
OTS BeagleBoard:
-rwxrw-r-- 1 gthomas gthomas    72014 Jan 22 10:12 
tmp/deploy/ipk/beagleboard/kernel-misc_2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1_beagleboard.ipk

I think this boils down to the actual kernel recipe - mine (attached) is
based on the older setup and includes "linux.inc" whereas the
BeagleBoard was built using a newer recipe which includes "linux-yocto.inc"
I tried just changing to use linux-yocto, but there seems to be much different
and nothing seemed to build properly anymore.  Any comments on this would
be appreciated.

At least now I know where the time is being spent...

-- 
------------------------------------------------------------
Gary Thomas                 |  Consulting for the
MLB Associates              |    Embedded world
------------------------------------------------------------

[-- Attachment #2: linux-am_2.6.32.bb --]
[-- Type: text/plain, Size: 420 bytes --]

require recipes-kernel/linux/linux.inc

DESCRIPTION = "My Linux kernel"

DEPENDS += "linux-firmware "
PV = "2.6.32"

# Note: defconfig comes from target recipe, as does the machine specific patchset
SRC_URI = "http://www.mlbassoc.com/repos/public/linux-am-${PV}.tar.bz2 \
           file://${MACHINE}.patch \
           file://defconfig \
"
LIC_FILES_CHKSUM = "file://COPYING;md5=d7810fab7487fb0aad327b76f1be7cd7 "

Re: What's taking so long??

[Xu, Dongxiao]

Gary Thomas wrote:
> On 01/21/2011 01:48 PM, Gary Thomas wrote:
>> On 01/21/2011 09:17 AM, Richard Purdie wrote:
>>> On Fri, 2011-01-21 at 07:25 -0700, Gary Thomas wrote:
>>>> This particular test was isolated, just that one recipe. I noticed
>>>> it before when building a complete image, so running it isolated
>>>> does not seem to make any difference. There is also nothing else
>>>> running on my build machine (it's a separate server that is used
>>>> only for builds)
>>>>
>>>> This is against master as of 2011-01-14
>>>> (897530621fabf3c345c302050a5c21e16097a2ba)
>>>> with my local layers.
>>>>
>>>> What can I look at (alternatively what data can I provide) to help
>>>> understand this?
>>>
>>> You could try pulling in:
>>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=ede381d56b180b384fd
>>> ad98d445e5430819cfade
>>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=7857834691868b7f48f
>>> 732ee78d8770f5473ff68
>>> http://git.pokylinux.org/cgit.cgi/poky/commit/?id=fd88588df029604689d
>>> b9b0e30c55aad68392a5d
>>>
>>> and see if they fix the problem. I'm not sure that they would in a
>>> single task case but who knows. You could also try adding timings as
>>> per my previous email, the change to package.bbclass was simply:
>>>
>>> diff --git a/meta/classes/package.bbclass
>>> b/meta/classes/package.bbclass index 8e7fa26..8b0cb96 100644
>>> --- a/meta/classes/package.bbclass
>>> +++ b/meta/classes/package.bbclass
>>> @@ -1082,6 +1082,7 @@ python package_do_package () { return
>>>
>>> for f in (bb.data.getVar('PACKAGEFUNCS', d, True) or '').split(): +
>>> bb.error("Running %s" % f) bb.build.exec_func(f, d)
>>> }
>>> do_package[dirs] = "${SHLIBSWORKDIR} ${PKGDESTWORK} ${D}"
>>>
>>> as I'd like to understand of the 23 minutes, where the time is
>>> being spent.
>>
>> For my board:
>> Fri Jan 21 10:12:13 MST 2011: NOTE: Running task 658 of 661 (ID: 11,
>> /home/local/poky-amltd/meta-amltd/packages/linux/linux-am_2.6.32.bb,
>> do_package) Fri Jan 21 10:12:13 MST 2011: NOTE: package
>> linux-am-2.6.32-r0: task do_package: Started Fri Jan 21 10:12:13 MST
>> 2011: ERROR: Running perform_packagecopy Fri Jan 21 10:12:27 MST
>> 2011:
>> ERROR: Running package_do_split_locales Fri Jan 21 10:12:27 MST 2011:
>> ERROR: Running populate_packages Fri Jan 21 10:12:27 MST 2011:
>> WARNING: <string>:5: RuntimeWarning: tmpnam is a potential security
>> risk to your program Fri Jan 21 10:12:27 MST 2011:
>> Fri Jan 21 10:12:45 MST 2011: NOTE: package linux-am-2.6.32-r0: task
>> do_populate_sysroot: Succeeded Fri Jan 21 10:28:33 MST 2011: ERROR:
>> Running package_do_filedeps Fri Jan 21 10:34:16 MST 2011: ERROR:
>> Running package_do_shlibs Fri Jan 21 10:34:21 MST 2011: ERROR:
>> Running
>> package_do_pkgconfig Fri Jan 21 10:34:23 MST 2011: ERROR: Running
>> read_shlibdeps Fri Jan 21 10:34:23 MST 2011: ERROR: Running
>> package_depchains Fri Jan 21 10:34:23 MST 2011: ERROR: Running
>> emit_pkgdata Fri Jan 21 10:34:23 MST 2011: ERROR: Running
>> do_package_qa
>>
>> For the BeagleBoard:
>> Fri Jan 21 13:32:22 MST 2011: NOTE: Running task 878 of 882 (ID: 17,
>> /home/local/poky-amltd/meta/recipes-kernel/linux/linux-yocto-stable_git.bb,
>> do_package) Fri Jan 21 13:32:22 MST 2011: NOTE: package
>> linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1:
>> task do_package: Started Fri Jan 21 13:32:23 MST 2011: ERROR:
>> Running perform_packagecopy Fri
>> Jan 21 13:32:25 MST 2011: ERROR: Running package_do_split_locales Fri
>> Jan 21 13:32:26 MST 2011: ERROR: Running populate_packages Fri Jan 21
>> 13:32:27 MST 2011: WARNING: <string>:5: RuntimeWarning: tmpnam is a
>> potential security risk to your program Fri Jan 21 13:32:27 MST 2011:
>> Fri Jan 21 13:32:31 MST 2011: NOTE: package
>> linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b7
>> 5_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1: task
>> do_populate_sysroot: Succeeded
>> Fri Jan 21 13:32:43 MST 2011: ERROR: Running package_do_filedeps Fri
>> Jan 21 13:35:52 MST 2011: ERROR: Running package_do_shlibs Fri Jan 21
>> 13:35:54 MST 2011: ERROR: Running package_do_pkgconfig Fri Jan 21
>> 13:35:54 MST 2011: ERROR: Running read_shlibdeps Fri Jan 21 13:35:55
>> MST 2011: ERROR: Running package_depchains Fri Jan 21 13:35:55 MST
>> 2011: ERROR: Running emit_pkgdata Fri Jan 21 13:35:55 MST 2011:
>> ERROR:
>> Running do_package_qa
>>
>> Interesting results. I'm going to run it again, with more messages in
>> the two time consuming steps - populate_packages &
>> package_do_filedeps
>>
>
> I've isolated it down to this section of code in 'populate_packages':
>
>       unshipped = []
>       for root, dirs, files in os.walk(dvar):
>               for f in files:
>                       path = os.path.join(root[len(dvar):], f)
>                       if ('.' + path) not in seen:
>                               unshipped.append(path)
>
>       if unshipped != []:
>               bb.note("the following files were installed but not shipped in any
>               package:") for f in unshipped:
>                       bb.note("  " + f)
>
> The difference comes from what's in that ".../package" tree.
> For my kernel:
>    $ find
>
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/package
> | wc 8567    8567 1098403
> For the OTS BeagleBoard kernel:
>    $ find
> /home/local/bb_poky/tmp/work/beagleboard-poky-linux-gnueabi/linux-yocto-stable-2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1/package
>> wc
>       1598    1598  364151
>
> I measured this and in the 'for f in unshipped:' loop above, each
> iteration is taking ~125ms!  I have a hard time understanding why,
> but 8567*125ms = 1070.875sec = 17.847min!

Hi Richard and Gary,

Kevin and I spent some time investigating this logging issue, and finally we found its cause.

The phenomenon is, if we write a task like:

testlog.bb:

python do_crazylog () {
        for i in range(500):
                bb.note("xdx: hello world.")
}
addtask crazylog

And run the command: "time bitbake testlog -c crazylog -f", it needs about 68 seconds to print the 500 sentences, which is problematic.

I used "bitbake -P" to do some profiling for this task, and found most time is costed by time.sleep(), and each time it will sleep 0.25 seconds.

Thu Jan 27 16:11:59 2011    profile.log

         922167 function calls (892080 primitive calls) in 69.882 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.012    0.012   69.887   69.887 /home/dongxiao/poky/bitbake/lib/bb/ui/knotty.py:67(main)
     1391    0.005    0.000   69.829    0.050 /home/dongxiao/poky/bitbake/lib/bb/server/none.py:95(waitEvent)
     1044    0.005    0.000   69.818    0.067 /home/dongxiao/poky/bitbake/lib/bb/server/none.py:121(idle_commands)
      265   66.350    0.250   66.350    0.250 {time.sleep}
      780    0.001    0.000    2.143    0.003 /home/dongxiao/poky/bitbake/lib/bb/cooker.py:156(runCommands)
      780    0.003    0.000    2.142    0.003 /home/dongxiao/poky/bitbake/lib/bb/command.py:91(runAsyncCommand)
      780    0.002    0.000    1.935    0.002 /home/dongxiao/poky/bitbake/lib/bb/cooker.py:738(updateCache)


I bisected the git log and found that the commit introduced this issue is a merge from openembedded.

After this commit, the whole LogRecord object into eventQueue, which contains more information than only level and messages.

Commit: d3a45c7d41a88d79389fc40eb68816e4939fb6f9.

    Use logging in the knotty ui, and pass the log record across directly

    This kills firing of Msg* events in favor of just passing along LogRecord
    objects.  These objects hold more than just level and message, but can also
    have exception information, so the UI can decide what to do with that.

    As an aside, when using the 'none' server, this results in the log messages in
    the server being displayed directly via the logging module and the UI's
    handler, rather than going through the server's event queue.  As a result of
    doing it this way, we have to override the event handlers of the base logger
    when spawning a worker process, to ensure they log via events rather than
    directly.


Based on our analysis of the current code, the main steps for logging is: (knotty ui and none server)

1) Each time when bitbake server fork off a task in execute(), it will create pipe between server and forked task.

2) Server will read the pipe to get "events", and then append it to the server eventQueue. Each time it will read 1024 bytes.

3) The UI module (knotty in our case) will wait on getting the event from eventQueue of "none" server, if there are events exist, it will handle the event. Otherwise, it will sleep 0.25 seconds and see there is any event.


Previsouly before the patch, we only put message and level information into eventQueue, thus each time in read(), we can read a bunch of messages in above case (about 10 "xdx: hello world.").

However, after passing the whole object, 1024 bytes could only cover 1, 2 or even zero LogRecord objects. Therefore the server is always "starve" to get event from the pipe, and thus the eventQueue is empty in most cases, which makes knotty ui sleep.

One of the straightforward idea is to change 1024 to be a bigger number, for example, 10240. See following patch.

diff --git a/bitbake/lib/bb/runqueue.py b/bitbake/lib/bb/runqueue.py
index b9d89ec..196b957 100644
--- a/bitbake/lib/bb/runqueue.py
+++ b/bitbake/lib/bb/runqueue.py
@@ -1637,7 +1637,7 @@ class runQueuePipe():
     def read(self):
         start = len(self.queue)
         try:
-            self.queue = self.queue + self.input.read(1024)
+            self.queue = self.queue + self.input.read(10240)
         except (OSError, IOError):
             pass
         end = len(self.queue)

I retested the above case, and it can get a much better results:

After patch:
real    0m9.994s
user    0m3.410s
sys     0m0.390s

Before patch:
real    1m8.614s
user    0m3.460s
sys     0m0.320s

This is a bottle neck for those cases which have a loop of "bb.note", like Gary found in the package bbclass for kernel recipes.

But for normal "bb.note", it may not benefit a lot. So this logging issue may be not a key point to the current long building time.

But anyhow, I am scheduling a test for this patch to see whether it helps for our common build result, like poky-image-minimal, etc.

Comments and thoughts on it?

Thanks,
Dongxiao


>
> I also found that later on, in 'do_filedeps()', some packages take an
> extraordinary amount of time.  Looking at a few:
> Sat Jan 22 09:17:55 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-image
> Sat Jan 22 09:17:55 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-image
> Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-dev
> Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-dev
> Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-vmlinux
> Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-vmlinux
> Sat Jan 22 09:17:56 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-misc
> Sat Jan 22 09:20:36 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-misc
> Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-crc-itu-t
> Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-crc-itu-t
> Sat Jan 22 09:23:28 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --provides
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-g-cdc
> Sat Jan 22 09:23:29 MST 2011: ERROR: do_filedeps:
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/perfile_rpmdeps.sh
> --rpmdeps
> /home/local/p60_poky/tmp/sysroots/i686-linux/usr/lib/rpm/rpmdeps
> --requires
> /home/local/p60_poky/tmp/work/cobra3530p60-poky-linux-gnueabi/linux-am-2.6.32-r0/packages-split/kernel-module-g-cdc
>
> You'll see that most take a few seconds (at most), but the
> 'kernel-misc'
> package is taking 6 minutes by itself!  This particular sub-package
> seems to be completely different between the two kernels.
> Mine:
> -rwxrw-r-- 1 gthomas gthomas  8627800 Jan 22 09:25
> tmp/deploy/ipk/cobra3530p60/kernel-misc_2.6.32-r0_cobra3530p60.ipk
> OTS BeagleBoard:
> -rwxrw-r-- 1 gthomas gthomas    72014 Jan 22 10:12
> tmp/deploy/ipk/beagleboard/kernel-misc_2.6.34+git0+ed446ecd29e8c0f81ab8630a2db652121eeb0b75_0+35521a5a70316785a67aca1de1d39a7b84c49ccf-r1_beagleboard.ipk
>
> I think this boils down to the actual kernel recipe - mine (attached)
> is based on the older setup and includes "linux.inc" whereas the
> BeagleBoard was built using a newer recipe which includes
> "linux-yocto.inc"
> I tried just changing to use linux-yocto, but there seems to be much
> different and nothing seemed to build properly anymore.  Any comments
> on this would be appreciated.
>
> At least now I know where the time is being spent...

Re: What's taking so long??

[Tian, Kevin]

> From: Xu, Dongxiao
> Sent: Friday, January 28, 2011 3:42 PM
> 
> This is a bottle neck for those cases which have a loop of "bb.note", like Gary
> found in the package bbclass for kernel recipes.
> 
> But for normal "bb.note", it may not benefit a lot. So this logging issue may be
> not a key point to the current long building time.
> 
> But anyhow, I am scheduling a test for this patch to see whether it helps for our
> common build result, like poky-image-minimal, etc.
> 
> Comments and thoughts on it?
> 

Another issue found in the test, which we're not sure whether we did it correctly, that
bb.debug is never printed out to the console even with -DDD. Dongxiao checked the
server side, that no record is passed from the child process regarding to debug info.

Is there any change to activate the debug message or is it a real issue?

Thanks
Kevin

Re: What's taking so long??

[Richard Purdie]

On Fri, 2011-01-28 at 15:42 +0800, Xu, Dongxiao wrote:
> Kevin and I spent some time investigating this logging issue, and
> finally we found its cause.
> 
> The phenomenon is, if we write a task like:
> 
> testlog.bb:
> 
> python do_crazylog () {
>         for i in range(500):
>                 bb.note("xdx: hello world.")
> }
> addtask crazylog
> 
> And run the command: "time bitbake testlog -c crazylog -f", it needs
> about 68 seconds to print the 500 sentences, which is problematic.
> 
> I used "bitbake -P" to do some profiling for this task, and found most
> time is costed by time.sleep(), and each time it will sleep 0.25
> seconds.
> 
> Thu Jan 27 16:11:59 2011    profile.log
> 
>          922167 function calls (892080 primitive calls) in 69.882 CPU
> seconds
> 
>    Ordered by: cumulative time
> 
>    ncalls  tottime  percall  cumtime  percall
> filename:lineno(function)
>         1    0.012    0.012   69.887
> 69.887 /home/dongxiao/poky/bitbake/lib/bb/ui/knotty.py:67(main)
>      1391    0.005    0.000   69.829
> 0.050 /home/dongxiao/poky/bitbake/lib/bb/server/none.py:95(waitEvent)
>      1044    0.005    0.000   69.818
> 0.067 /home/dongxiao/poky/bitbake/lib/bb/server/none.py:121(idle_commands)
>       265   66.350    0.250   66.350    0.250 {time.sleep}
>       780    0.001    0.000    2.143
> 0.003 /home/dongxiao/poky/bitbake/lib/bb/cooker.py:156(runCommands)
>       780    0.003    0.000    2.142
> 0.003 /home/dongxiao/poky/bitbake/lib/bb/command.py:91(runAsyncCommand)
>       780    0.002    0.000    1.935
> 0.002 /home/dongxiao/poky/bitbake/lib/bb/cooker.py:738(updateCache)
> 
> 
> I bisected the git log and found that the commit introduced this issue
> is a merge from openembedded.
> 
> After this commit, the whole LogRecord object into eventQueue, which
> contains more information than only level and messages.
> 
> Commit: d3a45c7d41a88d79389fc40eb68816e4939fb6f9.
> 
>     Use logging in the knotty ui, and pass the log record across
> directly
> 
>     This kills firing of Msg* events in favor of just passing along
> LogRecord
>     objects.  These objects hold more than just level and message, but
> can also
>     have exception information, so the UI can decide what to do with
> that.
> 
>     As an aside, when using the 'none' server, this results in the log
> messages in
>     the server being displayed directly via the logging module and the
> UI's
>     handler, rather than going through the server's event queue.  As a
> result of
>     doing it this way, we have to override the event handlers of the
> base logger
>     when spawning a worker process, to ensure they log via events
> rather than
>     directly.
> 
> 
> Based on our analysis of the current code, the main steps for logging
> is: (knotty ui and none server)
> 
> 1) Each time when bitbake server fork off a task in execute(), it will
> create pipe between server and forked task.
> 
> 2) Server will read the pipe to get "events", and then append it to
> the server eventQueue. Each time it will read 1024 bytes.
> 
> 3) The UI module (knotty in our case) will wait on getting the event
> from eventQueue of "none" server, if there are events exist, it will
> handle the event. Otherwise, it will sleep 0.25 seconds and see there
> is any event.
> 
> 
> Previsouly before the patch, we only put message and level information
> into eventQueue, thus each time in read(), we can read a bunch of
> messages in above case (about 10 "xdx: hello world.").
> 
> However, after passing the whole object, 1024 bytes could only cover
> 1, 2 or even zero LogRecord objects. Therefore the server is always
> "starve" to get event from the pipe, and thus the eventQueue is empty
> in most cases, which makes knotty ui sleep.
> 
> One of the straightforward idea is to change 1024 to be a bigger
> number, for example, 10240. See following patch.
> 
> diff --git a/bitbake/lib/bb/runqueue.py b/bitbake/lib/bb/runqueue.py
> index b9d89ec..196b957 100644
> --- a/bitbake/lib/bb/runqueue.py
> +++ b/bitbake/lib/bb/runqueue.py
> @@ -1637,7 +1637,7 @@ class runQueuePipe():
>      def read(self):
>          start = len(self.queue)
>          try:
> -            self.queue = self.queue + self.input.read(1024)
> +            self.queue = self.queue + self.input.read(10240)
>          except (OSError, IOError):
>              pass
>          end = len(self.queue)
> 
> I retested the above case, and it can get a much better results:
> 
> After patch:
> real    0m9.994s
> user    0m3.410s
> sys     0m0.390s
> 
> Before patch:
> real    1m8.614s
> user    0m3.460s
> sys     0m0.320s
> 
> This is a bottle neck for those cases which have a loop of "bb.note",
> like Gary found in the package bbclass for kernel recipes.
> 
> But for normal "bb.note", it may not benefit a lot. So this logging
> issue may be not a key point to the current long building time.
> 
> But anyhow, I am scheduling a test for this patch to see whether it
> helps for our common build result, like poky-image-minimal, etc.
> 
> Comments and thoughts on it?

Great work in tracking that down. I've merged a version into master but
I did increase the read value by another factor of 10 as my local tests
showed it to be beneficial. I was nearly tempted to remove the size all
together but didn't for the reasons I've outlined in the commit (task
scheduling fairness and the risk of a crazy task blocking the server
main loop).

I think this could well have a significant speed effect on things in
general, we'll soon find out I guess! :)

Cheers,

Richard

Re: What's taking so long??

[Richard Purdie]

On Fri, 2011-01-28 at 15:49 +0800, Tian, Kevin wrote:
> > From: Xu, Dongxiao
> > Sent: Friday, January 28, 2011 3:42 PM
> > 
> > This is a bottle neck for those cases which have a loop of "bb.note", like Gary
> > found in the package bbclass for kernel recipes.
> > 
> > But for normal "bb.note", it may not benefit a lot. So this logging issue may be
> > not a key point to the current long building time.
> > 
> > But anyhow, I am scheduling a test for this patch to see whether it helps for our
> > common build result, like poky-image-minimal, etc.
> > 
> > Comments and thoughts on it?
> > 
> 
> Another issue found in the test, which we're not sure whether we did it correctly, that
> bb.debug is never printed out to the console even with -DDD. Dongxiao checked the
> server side, that no record is passed from the child process regarding to debug info.
> 
> Is there any change to activate the debug message or is it a real issue?

There was a problem in bitbake which was fixed in:

http://git.pokylinux.org/cgit.cgi/poky/commit/?id=d7eebbe9dbf0d790d4af93466f5c27127cae0999

I think this was the likely cause of this observation.

Cheers,

Richard