5485 2013-11-06 12:16:59 +0000 Buildstats info and database entries doesn't match sometimes 2015-03-23 09:29:23 +0000 1 1 7 Build System, Metadata & Runtime Toaster toaster unspecified x86 Multiple VERIFIED WONTFIX Medium normal 1.6 M1 5300 1 andreea.b.proca marius.avram alexandru.c.georgescu alexandru.damian belen.barros.pena cristiana.voicu ionutx.chisanovici sgw stanciux.mihail --- --- No (bug/feature does not impact docs) oldest_to_newest 38579 0 andreea.b.proca 2013-11-06 12:16:59 +0000 The stats file: /home/brandusa/dora-toaster/build/tmp/buildstats/core-image-sato-qemux86/201311051554/expat-native-2.1.0-r0/do_fetch. Part of the stats file content: Event: TaskStarted. Started: 1383660092.00. expat-native-2.1.0-r0: do_fetch: Elapsed time: 0.01 seconds. CPU usage: 11.1%. EndTimeIO: 297560 StartTimeIO: 297548 In database: { "pk": 4119, "model": "orm.task", "fields": { "work_directory": "", "cpu_usage": "0.1", "task_executed": true, "disk_io": 1688, "line_number": 0, "path_to_sstate_obj": "", "sstate_checksum": "02efd1cf3485aa9c44e768e8b84f0461", "recipe": 184, "sstate_result": 0, "source_url": "", "elapsed_time": "2.170456", "logfile": "/home/brandusa/dora-toaster/build/tmp/work/x86_64-linux/expat-native/2.1.0-r0/temp/log.do_fetch.4324", "build": 1, "task_name": "do_fetch", "message": "recipe expat-native-2.1.0-r0: task do_fetch: Succeeded", "outcome": 0, "order": 347, "script_type": 1 } F ====================================================================== FAIL: test_quality_Task (orm.tests.WebHobTest) ---------------------------------------------------------------------- Traceback (most recent call last): File "/home/brandusa/dora-toaster/bitbake/lib/toaster/orm/tests.py", line 424, in test_quality_Task self.assertEqual(disk_io, float(task_values[i]["disk_io"])) AssertionError: 12.0 != 1688.0 39185 1 alexandru.damian 2013-12-02 14:06:20 +0000 In review poky-contrib: toaster/master. Buildstats gathering mechanism is changed, the race condition that may have happened here is no longer possible. 39619 2 alexandru.damian 2013-12-30 13:29:16 +0000 merged in origin/master:f8120984f459d193ce5ffa243137baf0e38d223e 39800 3 andreea.b.proca 2014-01-14 13:37:53 +0000 Stats file: Event: TaskStarted. Started: 1389700513.32. core-image-minimal-1.0-r0: do_populate_lic_setscene: Elapsed time: 0.49 seconds. Ended: 1389700513.81 In database: "pk": 1636,. "model": "orm.task",. "fields": { "work_directory": "",. "cpu_usage": "1.3",. "task_executed": true,. "disk_io": 488,. "line_number": 0,. "path_to_sstate_obj": "",. "sstate_checksum": "769dca759ea690036d40caee0627ae7a",. "recipe": 100,. "sstate_result": 0,. "source_url": "",. "elapsed_time": "0.160532",. "logfile": "/home/andreea/poky/build/tmp/work/qemux86-poky-linux/core-image-minimal/1.0-r0/temp/log.do_populate_lic_setscene.5748",. "build": 1,. "task_name": "do_populate_lic_setscene",. "message": "recipe core-image-minimal-1.0-r0: task do_populate_lic_setscene: Succeeded",. "outcome": 0,. "order": 1,. "script_type": 2 } Test result: FAIL: test_quality_Task (orm.tests.QualityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/home/andreea/poky/bitbake/lib/toaster/orm/tests.py", line 121, in test_quality_Task self.assertEqual(elapsed_time, float(task_values[i]["elapsed_time"])) AssertionError: 0.49 != 0.160532 master:1b636173ca88e5ccca1992f9a12367a1189fa674 40448 4 marius.avram 2014-02-19 10:03:01 +0000 I submitted a fix for the problem on the bitbake-devel@lists.openembedded.org mailing list, commit 3c9f2e6a0506700e661e53e21309b0f74897e2d2. As I mentioned in the commit message, the main problem is that BuildInfoHelper class was measuring separately the time for a task at the arrival of the events. Also that the task was measured between different events in buildstats and toaster. This was one of the causes for the mismatch. Another problem is that the storing of the dependency information takes about 20 seconds. This was shortened to about 10 seconds in commit 24119541fc14c64342f65e92c6efd3da08c9b930. But it was not enough for the desired accuracy. The solution includes a time member in the TaskBase class, which is initialized at creation time. This brings similar time between buildstat and toaster. Because buildstats is still measuring time separately I suggest to modify it to use the newly added member from TaskBase (after the current patches are merged). This will remove any other possible inconsistencies between times. 40467 5 alexandru.damian 2014-02-19 18:47:42 +0000 Can you please rebase on the latest toaster/master ? The event handling code changed slightly, so it needs rebaseing. 41690 6 marius.avram 2014-03-25 13:25:38 +0000 Solution merged to master:poky patches: f191ab0198e383cda37b0bfdfb6365d85499e36b and ba6caa021fea2edc5483bcde6d71122f2a2a871a 42223 7 ionutx.chisanovici 2014-04-03 13:29:25 +0000 Verified. Ionut C 47067 8 ionutx.chisanovici 2014-11-18 08:20:51 +0000 Hi guys, For 1.6.2 rc2, commit: 30b8d9378b8260e452552b806610dc9b6fe0b69f, the issue is not fixed. In database: sqlite> select cpu_usage from orm_task where id=675; cpu_usage = 6.1 In stats file: $ cat core-image-sato-qemux86/201411171101/ncurses-native-5.9-r15.1/do_patch | grep CPU CPU usage: 2.0% Cheers, Ionut C 47073 9 alexandru.damian 2014-11-18 10:18:54 +0000 Will not fix for 1.6.x series, master patches can't be easily backported. 49636 10 alexandru.c.georgescu 2015-03-23 09:29:23 +0000 Verified as per above comments.