If you look at http://taskotron-dev.fedoraproject.org/taskmaster/builders/x86_64/builds/12666 , it took 30 minutes to generate the rpmlint output, then it got killed with a timeout. But that's not our problem, rpmlint is slow. Our problem is that I tried to run it again and it took another 25-30 minutes for libtaskotron to process the results. Here's the log:
$ runtask -i kernel-3.16.1-300.fc21 -t koji_build -a x86_64 ../task-rpmlint/rpmlint.yml [libtaskotron:runner.py:228] 2014-08-26 10:57:54 DEBUG Parsed arguments: Namespace(arch=['x86_64'], debug=False, item='kernel-3.16.1-300.fc21', jobid='-1', override=[], task=['../task-rpmlint/rpmlint.yml'], type='koji_build') [libtaskotron:config.py:93] 2014-08-26 10:57:54 DEBUG Using config file: /etc/taskotron/taskotron.yaml [libtaskotron:config.py:64] 2014-08-26 10:57:54 DEBUG Using config profile: development [libtaskotron:koji_utils.py:129] 2014-08-26 10:57:55 INFO Querying Koji for a list of RPMS for: kernel-3.16.1-300.fc21 [libtaskotron:koji_utils.py:188] 2014-08-26 10:57:57 INFO Fetching 62 RPMs for: kernel-3.16.1-300.fc21 (into /var/tmp/taskotron/task-Eqfsjl) kernel-3.16.1-300.fc21.armv7hl.rpm | 34 kB 00:00:00 kernel-core-3.16.1-300.fc21.armv7hl.rpm | 15 MB 00:01:24 kernel-debuginfo-common-armv7hl-3.16.1-300.fc21.armv7hl.rpm | 42 MB 00:02:57 kernel-devel-3.16.1-300.fc21.armv7hl.rpm | 8.9 MB 00:00:44 kernel-headers-3.16.1-300.fc21.armv7hl.rpm | 910 kB 00:00:07 kernel-lpae-3.16.1-300.fc21.armv7hl.rpm | 34 kB 00:00:00 kernel-lpae-core-3.16.1-300.fc21.armv7hl.rpm | 13 MB 00:01:34 kernel-lpae-devel-3.16.1-300.fc21.armv7hl.rpm | 8.7 MB 00:01:02 kernel-lpae-modules-3.16.1-300.fc21.armv7hl.rpm | 9.8 MB 00:01:22 kernel-lpae-modules-extra-3.16.1-300.fc21.armv7hl.rpm | 799 kB 00:00:10 kernel-modules-3.16.1-300.fc21.armv7hl.rpm | 10 MB 00:01:19 kernel-modules-extra-3.16.1-300.fc21.armv7hl.rpm | 816 kB 00:00:09 kernel-tools-3.16.1-300.fc21.armv7hl.rpm | 84 kB 00:00:01 kernel-tools-libs-3.16.1-300.fc21.armv7hl.rpm | 39 kB 00:00:00 kernel-tools-libs-devel-3.16.1-300.fc21.armv7hl.rpm | 37 kB 00:00:00 perf-3.16.1-300.fc21.armv7hl.rpm | 853 kB 00:00:07 python-perf-3.16.1-300.fc21.armv7hl.rpm | 123 kB 00:00:01 kernel-3.16.1-300.fc21.i686.rpm | 34 kB 00:00:00 kernel-PAE-3.16.1-300.fc21.i686.rpm | 34 kB 00:00:00 kernel-PAE-core-3.16.1-300.fc21.i686.rpm | 17 MB 00:01:52 kernel-PAE-devel-3.16.1-300.fc21.i686.rpm | 8.9 MB 00:01:23 kernel-PAE-modules-3.16.1-300.fc21.i686.rpm | 16 MB 00:01:49 kernel-PAE-modules-extra-3.16.1-300.fc21.i686.rpm | 2.1 MB 00:00:29 kernel-PAEdebug-3.16.1-300.fc21.i686.rpm | 34 kB 00:00:00 kernel-PAEdebug-core-3.16.1-300.fc21.i686.rpm | 18 MB 00:02:28 kernel-PAEdebug-devel-3.16.1-300.fc21.i686.rpm | 8.9 MB 00:01:18 kernel-PAEdebug-modules-3.16.1-300.fc21.i686.rpm | 16 MB 00:01:57 kernel-PAEdebug-modules-extra-3.16.1-300.fc21.i686.rpm | 2.2 MB 00:00:28 kernel-core-3.16.1-300.fc21.i686.rpm | 17 MB 00:01:46 kernel-debug-3.16.1-300.fc21.i686.rpm | 34 kB 00:00:00 kernel-debug-core-3.16.1-300.fc21.i686.rpm | 18 MB 00:02:18 kernel-debug-devel-3.16.1-300.fc21.i686.rpm | 8.9 MB 00:00:33 kernel-debug-modules-3.16.1-300.fc21.i686.rpm | 16 MB 00:02:17 kernel-debug-modules-extra-3.16.1-300.fc21.i686.rpm | 2.2 MB 00:00:08 kernel-debuginfo-common-i686-3.16.1-300.fc21.i686.rpm | 47 MB 00:03:55 kernel-devel-3.16.1-300.fc21.i686.rpm | 8.9 MB 00:00:40 kernel-headers-3.16.1-300.fc21.i686.rpm | 933 kB 00:00:05 kernel-modules-3.16.1-300.fc21.i686.rpm | 16 MB 00:01:34 kernel-modules-extra-3.16.1-300.fc21.i686.rpm | 2.1 MB 00:00:20 kernel-tools-3.16.1-300.fc21.i686.rpm | 117 kB 00:00:00 kernel-tools-libs-3.16.1-300.fc21.i686.rpm | 41 kB 00:00:00 kernel-tools-libs-devel-3.16.1-300.fc21.i686.rpm | 37 kB 00:00:00 perf-3.16.1-300.fc21.i686.rpm | 1.0 MB 00:00:05 python-perf-3.16.1-300.fc21.i686.rpm | 128 kB 00:00:00 kernel-3.16.1-300.fc21.src.rpm | 77 MB 00:08:36 kernel-3.16.1-300.fc21.x86_64.rpm | 34 kB 00:00:00 kernel-core-3.16.1-300.fc21.x86_64.rpm | 18 MB 00:01:29 kernel-debug-3.16.1-300.fc21.x86_64.rpm | 34 kB 00:00:00 kernel-debug-core-3.16.1-300.fc21.x86_64.rpm | 19 MB 00:01:28 kernel-debug-devel-3.16.1-300.fc21.x86_64.rpm | 9.0 MB 00:00:41 kernel-debug-modules-3.16.1-300.fc21.x86_64.rpm | 18 MB 00:01:12 kernel-debug-modules-extra-3.16.1-300.fc21.x86_64.rpm | 2.3 MB 00:00:03 kernel-debuginfo-common-x86_64-3.16.1-300.fc21.x86_64.rpm | 48 MB 00:03:16 kernel-devel-3.16.1-300.fc21.x86_64.rpm | 8.9 MB 00:00:40 kernel-headers-3.16.1-300.fc21.x86_64.rpm | 933 kB 00:00:04 kernel-modules-3.16.1-300.fc21.x86_64.rpm | 17 MB 00:01:05 kernel-modules-extra-3.16.1-300.fc21.x86_64.rpm | 2.2 MB 00:00:05 kernel-tools-3.16.1-300.fc21.x86_64.rpm | 116 kB 00:00:00 kernel-tools-libs-3.16.1-300.fc21.x86_64.rpm | 41 kB 00:00:00 kernel-tools-libs-devel-3.16.1-300.fc21.x86_64.rpm | 37 kB 00:00:00 perf-3.16.1-300.fc21.x86_64.rpm | 987 kB 00:00:02 python-perf-3.16.1-300.fc21.x86_64.rpm | 128 kB 00:00:00 [libtaskotron:python_directive.py:154] 2014-08-26 11:53:51 INFO Executing Python: run_rpmlint.run() with args {'workdir': '/var/tmp/taskotron/task-Eqfsjl', 'koji_build': 'kernel-3.16.1-300.fc21'} STDOUT: kernel-devel.i686: W: spelling-error %description -l en_US makefiles -> make files, make-files, filmmakers kernel-devel.i686: W: no-documentation kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/check/signature.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/has/dma.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/ip/vs/tab/bits.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/media/tuner/max2165.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/serial/8250/dma.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/dm/cache.h kernel-devel.i686: E: incorrect-fsf-address /usr/src/kernels/3.16.1-300.fc21.i686/arch/x86/include/asm/vmx.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/early/printk/dbgp.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/bt/hcibpa10x.h kernel-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686/include/config/pata/artop.h <a veeeeery long output> kernel-PAEdebug-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686+PAEdebug/include/config/md/raid1.h kernel-PAEdebug-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686+PAEdebug/include/config/crypto/crct10dif.h kernel-PAEdebug-devel.i686: E: zero-length /usr/src/kernels/3.16.1-300.fc21.i686+PAEdebug/include/config/sata/sis.h 62 packages and 0 specfiles checked; 48405 errors, 55061 warnings. STDERR: [libtaskotron:resultsdb_directive.py:170] 2014-08-26 12:50:59 INFO Reporting to ResultsDB is disabled. Once enabled, the following would get reported: not ok - rpmlint for Koji build kernel-3.16.1-300.fc21 # FAIL --- details: output: |- kernel-devel.i686: W: spelling-error %description -l en_US makefiles -> make files, make-files, filmmakers <stripped out> 62 packages and 0 specfiles checked; 48405 errors, 55061 warnings. item: kernel-3.16.1-300.fc21 outcome: FAILED summary: rpmlint FAILED for kernel-3.16.1-300.fc21 type: koji_build ... [libtaskotron:resultsdb_directive.py:171] 2014-08-26 12:50:59 INFO Hint: Enabling debug output allows you to see unstripped values during variable export. [libtaskotron:runner.py:247] 2014-08-26 12:50:59 INFO Check execution finished.
It's not very visible, because there is no timestamp after rpmlint finished, but it's pretty much 30 minutes for them and 30 minutes for us.
Run this (or rather a smaller set of packages) through a profiler, find out what's so slow in our code and fix it. Give us some comparison of time spent before and after.
This ticket had assigned some Differential requests: D337 D351 D311
Oh, and if we still end up taking a lot of time for certain tasks, it might be a good idea to show an INFO message like "Computing blablabla results, this make take a while" (in case we know the output is really huge).
I don't know if I'm doing something wrong, but I cannot reproduce it. Running runtask.py -i kernel-3.16.1-300.fc21 -t koji_build ../task-rpmlint/rpmlint.yml took about 1.54 hours, but 1.4 hours was rpm downloading, 8.3 minutes (0.13 hours) was rpmlint. This is output from profiler:
runtask.py -i kernel-3.16.1-300.fc21 -t koji_build ../task-rpmlint/rpmlint.yml
7373459 function calls (5802410 primitive calls) in 5563.448 seconds Ordered by: cumulative time List reduced from 1649 to 50 due to restriction <50> ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 5563.449 5563.449 runtask.py:6(<module>) 1 0.000 0.000 5563.380 5563.380 runner.py:218(main) 1 0.000 0.000 5563.357 5563.357 runner.py:35(run) 1 0.000 0.000 5563.356 5563.356 runner.py:119(do_actions) 3 0.000 0.000 5563.356 1854.452 runner.py:93(do_single_action) 1 0.000 0.000 5058.182 5058.182 koji_directive.py:104(process) 1 0.001 0.001 5058.182 5058.182 koji_utils.py:169(get_nvr_rpms) 59 0.002 0.000 5056.514 85.704 file_utils.py:59(download) 59 0.001 0.000 5056.482 85.703 grabber.py:1109(urlgrab) 59 0.000 0.000 5056.466 85.703 grabber.py:1046(_retry) 59 0.000 0.000 5056.465 85.703 {apply} 59 0.002 0.000 5056.465 85.703 grabber.py:1156(retryfunc) 59 0.002 0.000 5056.446 85.702 grabber.py:1233(__init__) 59 0.001 0.000 5056.443 85.702 grabber.py:1594(_do_open) 118 0.003 0.000 5056.421 42.851 grabber.py:1697(_do_grab) 59 0.001 0.000 5056.393 85.702 grabber.py:1487(_do_perform) 59 5009.148 84.901 5056.392 85.702 {built-in method perform} 1 0.000 0.000 504.386 504.386 python_directive.py:187(process) 1 0.000 0.000 504.336 504.336 python_directive.py:139(execute) 1 0.000 0.000 504.335 504.335 run_rpmlint.py:5(run) 1 0.000 0.000 504.334 504.334 subprocess.py:516(call) 2 0.000 0.000 504.332 252.166 subprocess.py:475(_eintr_retry_call) 1 0.000 0.000 504.309 504.309 subprocess.py:1371(wait) 1 504.309 504.309 504.309 504.309 {posix.waitpid} 390688 5.844 0.000 33.391 0.000 grabber.py:1841(_progress_update) 391397 7.424 0.000 15.994 0.000 grabber.py:1852(_over_max_size) 2351886/783962 13.025 0.000 14.113 0.000 grabber.py:879(__getattr__) 166049 4.520 0.000 13.799 0.000 grabber.py:1271(_retrieve) 179390 8.976 0.000 8.976 0.000 {method 'write' of 'file' objects} 390145 1.958 0.000 6.062 0.000 progress.py:132(update) 13272 0.885 0.000 3.581 0.000 progress.py:234(_do_update) 1 0.000 0.000 1.668 1.668 koji_utils.py:110(nvr_to_urls) 2 0.000 0.000 1.667 0.834 __init__.py:1554(__call__) 2 0.000 0.000 1.667 0.834 __init__.py:1878(_callMethod) 2 0.000 0.000 1.667 0.834 __init__.py:1805(_sendCall) 2 0.000 0.000 1.667 0.834 __init__.py:1820(_sendOneCall) 447 1.117 0.002 1.117 0.002 {method 'recv' of '_socket.socket' objects} 4 0.078 0.019 0.825 0.206 {imp.load_source} 792576/792073 0.729 0.000 0.813 0.000 {len} 2 0.000 0.000 0.800 0.400 httplib.py:1009(getresponse) 2 0.000 0.000 0.799 0.400 httplib.py:402(begin) 18 0.003 0.000 0.798 0.044 socket.py:406(readline) 2 0.000 0.000 0.793 0.396 httplib.py:363(_read_status) 3 0.000 0.000 0.776 0.259 runner.py:52(_load_directive) 1 0.050 0.050 0.686 0.686 resultsdb_directive.py:5(<module>) 784394/784335 0.673 0.000 0.674 0.000 {hasattr} 1 0.046 0.046 0.635 0.635 resultsdb_api.py:19(<module>) 26662 0.614 0.000 0.634 0.000 progress.py:755(format_number) 79809 0.296 0.000 0.603 0.000 progress.py:79(add) 1 0.042 0.042 0.535 0.535 __init__.py:42(<module>)
cumtime is what we should look at. ~5563 seconds took runtask.py/runner.py (that isn't suprising since that's where whole program takes place), from that ~5058 seconds took koji_directive.py/grabber.py (that's downloading) and ~504 seconds took python_directive.py/run_rpmlint.py (that's rpmlint's time).
cumtime
There is only thing I think it could affect this - reporting to ResultsDB, but since you have also had ResultsDB disabled and you was able to reproduce it, I'm not sure what to do with it.
@jsedlak, which rpmlint code have you used? This problem was worked around by commit a775078, so if you used that one, you can't see it. You have to use addbeb6 or older. Was that the case?
a775078
addbeb6
I'm going to close this for the moment. We stopped putting all our check output into TAP (at least in rpmlint), because we don't process it anyway (maybe "yet"). We will deal with this once we adjust our reporting approach and hit this issue again. Until then, there's no point in having this ticket opened.
Well, that didn't take too long and I reopen it. Look here: http://taskotron-dev.fedoraproject.org/taskmaster/builders/x86_64/builds/80582/steps/runtask/logs/stdio
It took 23 minutes for (most probably) libtaskotron to covert results to TAP:
[depcheck:__init__.py:121] 2015-03-08 10:42:10 INFO Formatting output [depcheck:__init__.py:128] 2015-03-08 11:05:36 INFO TAP version 13
and we were lucky buildbot watchdog hasn't killed it. We were not that lucky the second time:
[depcheck:__init__.py:121] 2015-03-08 11:07:10 INFO Formatting output command timed out: 1200 seconds without output, attempting to kill process killed by signal 9
Something takes really long in there. I assume it's a string manipulation for CheckDetail.output. Try to write a simple reproducer script (simply spit out a lot of output) and find out what's wrong.
CheckDetail.output
Well, it seems that problem is in yamlish, current code uses + to create output string (and creating new instance every time):
+
inobj = u"" for line in source: try: if not py3k or isinstance(line, bytes): line = line.decode('utf8') inobj += line + u'\n' except UnicodeDecodeError: if ignore_wrong_characters: inobj += line.decode('utf8', 'ignore') + '\n' else: raise out = load(inobj, ignore_wrong_characters)
when changed to this:
inobj = [] for line in source: try: if not py3k or isinstance(line, bytes): line = line.decode('utf8') inobj.append(line) except UnicodeDecodeError: if ignore_wrong_characters: inobj.append(line.decode('utf8', 'ignore')) else: raise out = load('\n'.join(inobj), ignore_wrong_characters)
I was able to significantly reduce running time.
I will ping Matej Cepl about this.
Well, this seems to be solved. Closing (D311).
Fixed in yamlish 0.18.0 (https://pypi.python.org/pypi/yamlish/0.18.0)
Metadata Update from @kparal: - Issue tagged with: easyfix
Login to comment on this ticket.