On Tue, Mar 11, 2014 at 4:13 AM, Sebastian Huber
<sebastian.hu...@embedded-brains.de> wrote:
> On 2014-03-10 16:52, Gedare Bloom wrote:
>>
>> On Mon, Mar 10, 2014 at 9:28 AM, Sebastian Huber
>> <sebastian.hu...@embedded-brains.de> wrote:
>>>
>>> ---
>>> cpukit/sapi/include/rtems/profiling.h | 88
>>> ++++++++++++++++++++++++++++++++-
>>> cpukit/sapi/src/profilingreportxml.c | 70 ++++++++++++++++++++++++++
>>> 2 files changed, 157 insertions(+), 1 deletions(-)
>>>
>>> diff --git a/cpukit/sapi/include/rtems/profiling.h
>>> b/cpukit/sapi/include/rtems/profiling.h
>>> index ecb3ff7..2a66015 100644
>>> --- a/cpukit/sapi/include/rtems/profiling.h
>>> +++ b/cpukit/sapi/include/rtems/profiling.h
>>> @@ -66,7 +66,14 @@ typedef enum {
>>> *
>>> * @see rtems_profiling_per_cpu.
>>> */
>>> - RTEMS_PROFILING_PER_CPU
>>> + RTEMS_PROFILING_PER_CPU,
>>> +
>>> + /**
>>> + * @brief Type of SMP lock profiling data.
>>> + *
>>> + * @see rtems_profiling_smp_lock.
>>> + */
>>> + RTEMS_PROFILING_SMP_LOCK
>>> } rtems_profiling_type;
>>>
>>> /**
>>> @@ -152,6 +159,80 @@ typedef struct {
>>> } rtems_profiling_per_cpu;
>>>
>>> /**
>>> + * @brief Count of lock contention counters for SMP lock profiling.
>>> + */
>>> +#define RTEMS_PROFILING_SMP_LOCK_CONTENTION_COUNTS 4
>>> +
>>> +/**
>>> + * @brief SMP lock profiling data.
>>> + *
>>> + * The lock acquire attempt instant is the point in time right after the
>>> + * interrupt disable action in the lock acquire sequence.
>>> + *
>>> + * The lock acquire instant is the point in time right after the lock
>>> + * acquisition. This is the begin of the critical section code
>>> execution.
>>> + *
>>> + * The lock release instant is the point in time right before the
>>> interrupt
>>> + * enable action in the lock release sequence.
>>> + *
>>> + * The lock section time is the time elapsed between the lock acquire
>>> instant
>>> + * and the lock release instant.
>>> + *
>>> + * The lock acquire time is the time elapsed between the lock acquire
>>> attempt
>>> + * instant and the lock acquire instant.
>>
>> Move this last point up to where you define lock acquire attempt
>> instant and lock acquire instant.
>
>
> Ok.
>
>
>>
>>> + */
>>> +typedef struct {
>>> + /**
>>> + * @brief The profiling data header.
>>> + */
>>> + rtems_profiling_header header;
>>> +
>>> + /**
>>> + * @brief The lock name.
>>> + */
>>> + const char *name;
>>> +
>>> + /**
>>> + * @brief The maximum lock section time in nanoseconds.
>>> + */
>>> + uint32_t max_section_time;
>>> +
>>> + /**
>>> + * @brief The maximum lock acquire time in nanoseconds.
>>> + */
>>> + uint32_t max_acquire_time;
>>> +
>>
>> Any possible issues with 32-bit values here?
>
>
> It would be a major bug if you spend 4 seconds in an SMP lock.
>
>
>>
>>> + /**
>>> + * @brief The count of lock uses.
>>> + *
>>> + * This value may overflow.
>>> + */
>>> + uint64_t usage_count;
>>> +
>>> + /**
>>> + * @brief Total lock section time in nanoseconds.
>>> + *
>>> + * The average lock section time is the total section time divided by
>>> the
>>> + * lock usage count.
>>> + *
>>> + * This value may overflow.
>>> + */
>>> + uint64_t total_section_time;
>>> +
>>> + /**
>>> + * @brief The counts of lock acquire operations by contention.
>>> + *
>>> + * The contention count for index N corresponds to a lock acquire
>>> attempt
>>> + * with an initial queue length of N. The last index corresponds to
>>> all
>>> + * lock acquire attempts with an initial queue length greater than or
>>> equal
>>> + * to RTEMS_PROFILING_SMP_LOCK_CONTENTION_COUNTS minus one.
>>> + *
>>> + * The values may overflow.
>>> + */
>>> + uint64_t
>>> contention_counts[RTEMS_PROFILING_SMP_LOCK_CONTENTION_COUNTS];
>>
>> contention_counts[0] is when there is no contention hence negligible
>> acquire_time?
>
>
> Yes, optimally you get the high numbers for contention_counts[0]. In case
> of the Giant lock it looks like this (smptests/smpload01):
>
> <SMPLockProfilingReport name="Giant">
> <MaxSectionTime unit="ns">233360</MaxSectionTime>
> <MaxAcquireTime unit="ns">192160</MaxAcquireTime>
> <UsageCount>9281</UsageCount>
> <TotalSectionTime unit="ns">464815740</TotalSectionTime>
> <ContentionCount initialQueueLength="0">2480</ContentionCount>
> <ContentionCount initialQueueLength="1">3893</ContentionCount>
> <ContentionCount initialQueueLength="2">2201</ContentionCount>
> <ContentionCount initialQueueLength="3">707</ContentionCount>
> </SMPLockProfilingReport>
>
>
>
>>
>> Is total_acquire_time not feasible or interesting to profile?
>
> [...]
>
> Hm, a good question. I think the contention counter and the total acquire
> time are a measure for lock contention. The ratio of total_acquire_time /
> total_section_time might be interesting.
>
> Should I add it?
>
Yes, it should be relatively cheap to do and gives a better idea
whether the contention is leading long delays or just a lot of small
ones.
> --
> Sebastian Huber, embedded brains GmbH
>
> Address : Dornierstr. 4, D-82178 Puchheim, Germany
> Phone : +49 89 189 47 41-16
> Fax : +49 89 189 47 41-09
> E-Mail : sebastian.hu...@embedded-brains.de
> PGP : Public key available on request.
>
> Diese Nachricht ist keine geschäftliche Mitteilung im Sinne des EHUG.
_______________________________________________
rtems-devel mailing list
rtems-devel@rtems.org
http://www.rtems.org/mailman/listinfo/rtems-devel
