siggen: print get_taskhash() time

  # Tested with rather big directory in EXTERNALSRC:
  #   $ find src | wc -l
  #   139261
  #   $ du -hs src
  #   2.4G    src

  # with even bigger directory:
  #   $ find | wc -l
  #   854949
  #   $ du -hs .
  #   41G     .
  # I didn't have enough patience as the current bitbake-2.0 didn't finish in 16 hours

current bitbake-2.0:

Initialising tasks...
WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.1920928955078125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.1920928955078125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 1.8835067749023438e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 1.9073486328125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 4.601478576660156e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 3.0994415283203125e-06 seconds
Bitbake still alive (no events for 600s). Active tasks:
Bitbake still alive (no events for 1200s). Active tasks:
Bitbake still alive (no events for 1800s). Active tasks:
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 1539.2191841602325 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 7.62939453125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 4.76837158203125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 6.4849853515625e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 4.76837158203125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 3.814697265625e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 3.457069396972656e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 8.106231689453125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 1.049041748046875e-05 seconds
done.
Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete)

bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717:

Initialising tasks...
WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.1920928955078125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 2.3126602172851562e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.430511474609375e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 2.86102294921875e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 3.933906555175781e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 3.5762786865234375e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 0.09659457206726074 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 6.9141387939453125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 2.6226043701171875e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 3.814697265625e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 5.6743621826171875e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 2.86102294921875e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 7.3909759521484375e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 2.765655517578125e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 8.821487426757812e-06 seconds
done.
Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete)

bitbake-2.0 with extend+join

Initialising tasks...
WARNING: get_taskhash[externalsrc_1.0.bb:do_deploy_source_date_epoch] took 1.6689300537109375e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_lic] took 1.1920928955078125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 8.106231689453125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_unpack] took 1.6689300537109375e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 4.0531158447265625e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure] took 4.291534423828125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 0.12246251106262207 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 1.5020370483398438e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_configure_manifest] took 3.0994415283203125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_populate_sysroot] took 3.814697265625e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 6.270408630371094e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_packagedata] took 2.86102294921875e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 6.9141387939453125e-06 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 2.86102294921875e-05 seconds
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 9.775161743164062e-06 seconds
done.
Sstate summary: Wanted 107 Local 107 Mirrors 0 Missed 0 Current 843 (100% match, 100% complete)

I've run it again in reversed order (printing only tasks with get_taskhash times >= 0.01 ms)
do_compile get_taskhash 1537328.01 -> 118.51 -> 93.15 ms

bitbake-2.0 with extend+join
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 93.15 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms

bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717:
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.05 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 118.51 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.02 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms

current bitbake-2.0:
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 1537328.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.05 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms

with whole 40G repo (running only with backport and with extend+join),
but this time the much longer time was spent in calculating those
checksums (when cache was removed between runs):
138M    cache/local_file_checksum_cache.dat

with 40G repo (also shows 6 warnings due to broken symlinks like:
WARNING: Unable to get checksum for externalsrc SRC_URI entry securegcm:
[Errno 2] No such file or directory:
'/OE/.../chromium/src/third_party/nearby/src/third_party/ukey2/include/securegcm')

chromium/src/third_party/nearby/src/third_party/ukey2/include/securegcm
-> ../ukey2/src/main/cpp/include/securegcm

WARNING: get_checksums[externalsrc] took 43443.56 ms
instead of:
WARNING: get_checksums[externalsrc] took 4206.65 ms
with 2.4G repo with:
22M     cache/local_file_checksum_cache.dat

bitbake-2.0 with backported https://git.openembedded.org/bitbake/commit/?id=195750f2ca355e29d51219c58ecb2c1d83692717:
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.02 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 680.98 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.06 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.03 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms

bitbake-2.0 with extend+join:
WARNING: get_taskhash[externalsrc_1.0.bb:do_fetch] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_prepare_recipe_sysroot] took 0.04 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_compile] took 794.98 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_install] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package] took 0.05 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_write_ipk] took 0.04 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_package_qa] took 0.01 ms
WARNING: get_taskhash[externalsrc_1.0.bb:do_build] took 0.01 ms

Signed-off-by: Martin Jansa <Martin.Jansa@gmail.com>

2 files changed, 12 insertions, 0 deletions

diff --git a/lib/bb/checksum.py b/lib/bb/checksum.py
index 557793d36..b4a6e74b3 100644
--- a/lib/bb/checksum.py
+++ b/lib/bb/checksum.py
@@ -111,6 +111,9 @@ class FileChecksumCache(MultiProcessCache):
                         dirchecksums.append((fullpth, checksum))
             return dirchecksums
 
+        import time
+        start_time = time.time()
+
         checksums = []
         for pth in filelist_regex.split(filelist):
             if not pth:
@@ -141,4 +144,7 @@ class FileChecksumCache(MultiProcessCache):
                     checksums.append((pth, checksum))
 
         checksums.sort(key=operator.itemgetter(1))
+        stop_time = time.time()
+        if "webruntime" in pn:
+            bb.warn("get_checksums[%s] took %s ms" % (pn, round((stop_time - start_time)*1000, 2)))
         return checksums
diff --git a/lib/bb/siggen.py b/lib/bb/siggen.py
index 9a20fc8e5..c74d9be73 100644
--- a/lib/bb/siggen.py
+++ b/lib/bb/siggen.py
@@ -326,6 +326,8 @@ class SignatureGeneratorBasic(SignatureGenerator):
         return
 
     def get_taskhash(self, tid, deps, dataCaches):
+        import time
+        start_time = time.time()
 
         data = self.basehash[tid]
         for dep in self.runtaskdeps[tid]:
@@ -345,6 +347,10 @@ class SignatureGeneratorBasic(SignatureGenerator):
 
         h = hashlib.sha256(data.encode("utf-8")).hexdigest()
         self.taskhash[tid] = h
+        stop_time = time.time()
+        if "webruntime" in tid:
+            bb.warn("get_taskhash[%s] took %s ms" % (tid, round((stop_time - start_time)*1000, 2)))
+
         #d.setVar("BB_TASKHASH:task-%s" % task, taskhash[task])
         return h