| Summary: | Buildstats info and database entries doesn't match sometimes | ||
|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] Toaster | Reporter: | Andreea Brandusa Proca <andreea.b.proca> |
| Component: | toaster | Assignee: | Marius Avram <marius.avram> |
| Status: | VERIFIED WONTFIX | QA Contact: | Mihail Stanciu <stanciux.mihail> |
| Severity: | normal | ||
| Priority: | Medium | CC: | alexandru.c.georgescu, alexandru.damian, belen.barros.pena, cristiana.voicu, ionutx.chisanovici, sgw |
| Version: | unspecified | ||
| Target Milestone: | 1.6 M1 | ||
| Hardware: | x86 | ||
| OS: | Multiple | ||
| Whiteboard: | |||
| OS type for building Yocto: | --- | Type of Regression: | --- |
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |
| Bug Depends on: | |||
| Bug Blocks: | 5300 | ||
In review poky-contrib: toaster/master. Buildstats gathering mechanism is changed, the race condition that may have happened here is no longer possible. merged in origin/master:f8120984f459d193ce5ffa243137baf0e38d223e 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
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. Can you please rebase on the latest toaster/master ? The event handling code changed slightly, so it needs rebaseing. Solution merged to master:poky patches: f191ab0198e383cda37b0bfdfb6365d85499e36b and ba6caa021fea2edc5483bcde6d71122f2a2a871a Verified. Ionut C 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 Will not fix for 1.6.x series, master patches can't be easily backported. Verified as per above comments. |
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