Re: What's taking so long??

[Gary Thomas <gary@mlbassoc.com>]

[-- 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 "