Coverage analysis update
Cillian O'Donnell
cpodonnell8 at gmail.com
Thu Jul 6 21:14:15 UTC 2017
On 6 July 2017 at 19:14, Joel Sherrill <joel at rtems.org> wrote:
>
>
> On Thu, Jul 6, 2017 at 11:11 AM, Cillian O'Donnell <cpodonnell8 at gmail.com>
> wrote:
>>
>> On 6 July 2017 at 15:34, Joel Sherrill <joel at rtems.org> wrote:
>> >
>> >
>> > On Thu, Jul 6, 2017 at 5:53 AM, Cillian O'Donnell
>> > <cpodonnell8 at gmail.com>
>> > wrote:
>> >>
>> >> On 6 July 2017 at 08:05, Chris Johns <chrisj at rtems.org> wrote:
>> >> > On 05/07/2017 22:46, Cillian O'Donnell wrote:
>> >> >>
>> >> >> Now the thing is, I might have to run RTEMS Tester about 3 times for
>> >> >> the full testsuite before I can get the report, as the covoar runs
>> >> >> will often hang on an arbitrary method and have to be manually
>> >> >> exited
>> >> >> and re-run.
>> >> >
>> >> > How is covoar being run? Is it being run by the 'rtems-test' command?
>> >>
>> >> Yes covoar runs after the testsuite if a --coverage flag is included
>> >> with rtems-test command.
>> >> >
>> >> >> The point that this happens is not repeatable and there's
>> >> >> no error message to go on.
>> >> >
>> >> > Is it the covoar process that is stopping? Is it the process idle or
>> >> > using 100%?
>> >>
>> >> Covoar locks up and becomes idle. Joel mentioned in the IRC meeting
>> >> he's seen it before and I'll need to track down the exe causing it and
>> >> debug it to get rid of this
>> >
>> >
>> > There must be a misunderstanding. I have never seen covoar lock up
>> > like this.
>>
>> Oh sorry, you must of just meant debugging covoar in general, picked
>> it up wrong.
>> >
>> > It will ignore records when it thinks things are inconsistent. This can
>> > occur
>> > when a method appears in two different executables and has different
>> > sizes. The cause of this is usually padding at the end of the method so
>> > the subsequent method in memory starts on a nice cache-line alignment.
>> > The code tries to recognize the nops/padding at the end and ignore them.
>> > When the padding inserted by ld changes or the objdump output being
>> > parsed changes, covoar needs to be adjusted.
>> >
>> > The ignored record message I saw is in the code that reads Couverture
>> > trace records. The info in the record appears to be inconsistent with
>> > the
>> > code to which it has been matched. This could be because the trace
>> > record format has been changed or a simple bug.
>> >
>> > From what I have seen, it is likely that it is primarily bugs in input
>> > processing.
>> >
>> > But the code to do the "big union" of the trace data has to iterate over
>> > all tests and all coverage blocks. It can take a while to run. I guess
>> > there could be an infinite loop in it. I always debugged it by having
>> > a test case I could run in gdb.
>> >
>> >>
>> >> >
>> >> >> The only common theme is the methods will
>> >> >> often be called thread...something. Even more rarely it will stop
>> >> >> with
>> >> >> the message 'resource temporarily unavailable'. I'm wondering is
>> >> >> this
>> >> >> normal behaviour for covoar on a long test-run? This never happens
>> >> >> when running just the samples.
>> >> >
>> >> > It is not normal behavior.
>> >
>> >
>> > +1
>> >
>> > Is Linux or covoar printing the message? It holds all data in memory
>> > while
>> > doing the analysis. Is it consuming a lot of RAM?
>>
>> I done two rtems-test coverage runs there while monitoring 'top'
>> output. The first run is successful and coverage report is generated
>> and the second run produced IO Error: Resource temporarily unavailable
>> on the second. Both times theres about 3.5-4GB RAM free and CPU runs
>> at 70-80% so nothing seems to be strained there.
>> Timecounter_Tick_simple is being checked before it happens. The output
>> is
>>
>> 4000c9d8: 0a 80 00 03 bcs 4000c9e4 <_Timecounter_Tick_simple+0x78>
>> 4000c9dc: 84 01 20 01 add %g4, 1, %g2
>>
>> bt = th->th_offset;
>> 4000c9e0: 84 10 00 04 mov %g4, %g2
>> _bt->sec += _bt2->sec;
>> 4000c9e4: fa 06 e0 a0 ld [ %i3 + 0xa0 ], %i5
>> 4000c9e8: 84 00 80 1d add %g2, %i5, %g2
>> _tv->tv_usec = ((uint64_t)1000000 * (uint32_t)(_bt->frac >> 32)) >>
>> 32;
>> 4000c9ec: 39 00 03 d0 sethi %hi(0xf4000), %i4
>> _ts->tv_nsec = ((uint64_t)1000000000 *
>> 4000c9f0: 3b 0e e6 b2 sethi %hi(0x3b9ac800), %i5
>> _tv->tv_usec = ((uint64_t)1000000 * (uint32_t)(_bt->frac >> 32)) >>
>> 32;
>> 4000c9f4: b8 17 22 40 or %i4, 0x240, %i4
>> _ts->tv_nsec = ((uint64_t)1000000000 *
>> 4000c9f8: ba 17 62 00 or %i5, 0x200, %i5
>> _tv->tv_usec = ((uint64_t)1000000 * (uint32_t)(_bt->frac >> 32))
>> >> 32;Exception in thread _stderr[c]:
>> Traceback (most recent call last):
>> File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
>> self.run()
>> File "/usr/lib/python2.7/threading.py", line 754, in run
>> self.__target(*self.__args, **self.__kwargs)
>> File
>> "/home/cpod/development/rtems/test/rtems-tools/rtemstoolkit/execute.py",
>> line 206, in _readthread
>> _output_line(line, exe, prefix, out, count)
>> File
>> "/home/cpod/development/rtems/test/rtems-tools/rtemstoolkit/execute.py",
>> line 184, in _output_line
>> out(prefix + line)
>> File
>> "/home/cpod/development/rtems/test/rtems-tools/tester/rt/coverage.py",
>> line 387, in output_handler
>> log.notice(text, stdout_only = False)
>> File
>> "/home/cpod/development/rtems/test/rtems-tools/rtemstoolkit/log.py",
>> line 104, in notice
>> print(l)
>> IOError: [Errno 11] Resource temporarily unavailable
>
>
> This looks like qemu is running too long with an RTEMS executable. This
> stack trace is RTEMS code. Not covoar code. Please check what executable
> is consuming so much run-time before it is killed. This will change the
> solution. :)
>
> covoar spends a lot of time iterating over sets of containers and
> executables.
> There could be an infinite loop in it but it is using STL containers for
> everything and is single threaded so I rather doubt it would go into an
> infinite loop.
The executable running here is sprmsched01.exe I produced it again and
it was sp22.exe nnd then again with psxaio01.exe so it doesn't seem to
pin point a single test repeatably.
>
>>
>>
>> >
>> >>
>> >> >> When a test run is successful it will also finish with a lot of
>> >> >> these
>> >> >> messages:
>> >> >>
>> >> >> *** Trace block is inconsistent with coverage map
>> >> >> *** Trace block (0x4000c4fc - 0x4000c51f) for 36 bytes
>> >> >> *** Coverage map
>> >> >> /home/cpod/coverage_test/test/coverage/unlimited.exe.cov
>> >> >> INFO: DesiredSymbols::mergeCoverageMap - Unable to merge coverage
>> >> >> map
>> >> >> for _Thread_queue_Extract_with_proxy because the sizes are different
>> >> >
>> >> > I wonder what sizes are different?
>> >>
>> >> For this one, Joel mentioned it could be something to do with nops
>> >> being added or space not matching and to take a look at _Thread_
>> >> queue_Extract_with_proxy in the objdump and see if I can dig up
>> >> anything from that. That message appears for _Thread_
>> >> queue_Extract_with_proxy on all tests from base_sp.exe to
>> >> unlimited.exe when running the full testsuite and on a few instances
>> >> it also mentions unable to merge coverage map for TOD_TICKS_PER_SECOND
>> >> for the same reason. The mismatch is always 36 bytes.
>> >
>> >
>> > You need to find the two executables it differs on and see why the size
>> > is different. It processes them from first to last on the command line
>> > so
>> > find the first one that has the symbol and compare the dump to that
>> > one it is flagging as different.
>>
>> Will the 2 executables be say for example unlimited.exe from the build
>> tree and the temporarily copied covoar executable unlimited.exe.cov?
>> So libscore.a info matches the original unlimited.exe and something
>> has changed in the covoar copies?
>
>
> No. It will be unlimited and one of the tests before it on the covoar
> command line. In particular, it should be the first one with the symbol
> in question. Compare the objdump's.
Ok I just checked and the first instance is base_sp.exe, which is
actually the first test run so this appears for every single test.
Where we hoping to compare one without the problem to the one it first
appears on?
>
>
>>
>> >>
>> >>
>> >> Also I wanted to mention, there is quite a bit of work from the 2
>> >> previous students on the integration of the coverage work into RTEMS
>> >> Tester, would you be interested in starting the merging process of
>> >> this. It might take a while to get everything reviewed and make any
>> >> necessary changes. At this point it is working. its just fixing bugs,
>> >> which I'm working on at the moment.
>> >
>> >
>> > Chris.. I suggested this. It seems the basic flow and integration of
>> > coverage into the tester is good enough to review and merge.
>> >
>> > --joel
>> >
>> >>
>> >>
>> >> Thanks,
>> >>
>> >> Cillian.
>> >> >
>> >> > Chris
>> >> _______________________________________________
>> >> devel mailing list
>> >> devel at rtems.org
>> >> http://lists.rtems.org/mailman/listinfo/devel
>> >
>> >
>
>
More information about the devel
mailing list