test: timer: relaxed timing checks

Message ID 1421097657-7433-1-git-send-email-ola.liljedahl@linaro.org
State New
Headers show

Commit Message

Ola Liljedahl Jan. 12, 2015, 9:20 p.m.
Don't report too late timeouts using CU_FAIL as this interferes with the cunit
test framework. Just count and report (using LOG_DBG) the number of late
timeouts.
Use CU_ASSERT_FATAL instead of plain assert so to work wither with the cunit
test framework.
Don't dereference pointer after successful check for NULL as this makes Coverity
complain.
Use LOG_DBG instead of printf. Remove some unnecessary printouts.
Use nanosleep instead of the deprecated usleep.

Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
---
(This document/code contribution attached is provided under the terms of
agreement LES-LTM-21309)

 test/validation/odp_timer.c | 102 +++++++++++++++++++++++++-------------------
 1 file changed, 59 insertions(+), 43 deletions(-)

Comments

Mike Holmes Jan. 13, 2015, 7:15 p.m. | #1
On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:

> Don't report too late timeouts using CU_FAIL as this interferes with the
> cunit
> test framework. Just count and report (using LOG_DBG) the number of late
> timeouts.
> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
> cunit
> test framework.
> Don't dereference pointer after successful check for NULL as this makes
> Coverity
> complain.
> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> Use nanosleep instead of the deprecated usleep.
>
> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>

Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>


> ---
> (This document/code contribution attached is provided under the terms of
> agreement LES-LTM-21309)
>
>  test/validation/odp_timer.c | 102
> +++++++++++++++++++++++++-------------------
>  1 file changed, 59 insertions(+), 43 deletions(-)
>
> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
> index 4c93f71..d893646 100644
> --- a/test/validation/odp_timer.c
> +++ b/test/validation/odp_timer.c
> @@ -8,10 +8,13 @@
>   * @file
>   */
>
> -#include <assert.h>
> +/* For rand_r and nanosleep */
> +#define _POSIX_C_SOURCE 200112L
> +#include <time.h>
>  #include <unistd.h>
>  #include <odp.h>
>  #include "odp_cunit_common.h"
> +#include "test_debug.h"
>
>  /** @private Timeout range in milliseconds (ms) */
>  #define RANGE_MS 2000
> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>  /** @private Timer pool handle used by all threads */
>  static odp_timer_pool_t tp;
>
> +/** @private Count of timeouts delivered too late */
> +static odp_atomic_u32_t ndelivtoolate;
> +
>  /** @private min() function */
>  static int min(int a, int b)
>  {
> @@ -47,8 +53,7 @@ struct test_timer {
>  /* @private Handle a received (timeout) buffer */
>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t prev_tick)
>  {
> -       /* Use assert() for internal correctness checks of test program */
> -       assert(buf != ODP_BUFFER_INVALID);
> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error */
>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>                 /* Not a timeout buffer */
>                 CU_FAIL("Unexpected buffer type received");
> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool stale,
> uint64_t prev_tick)
>         if (ttp == NULL)
>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>
> -       if (ttp->buf2 != buf)
> +       if (ttp != NULL && ttp->buf2 != buf)
>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
> -       if (ttp->tim != tim)
> +       if (ttp != NULL && ttp->tim != tim)
>                 CU_FAIL("odp_timeout_timer() wrong timer");
>         if (stale) {
>                 if (odp_timeout_fresh(tmo))
>                         CU_FAIL("Wrong status (fresh) for stale timeout");
>                 /* Stale timeout => local timer must have invalid tick */
> -               if (ttp->tick != TICK_INVALID)
> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>                         CU_FAIL("Stale timeout for active timer");
>         } else {
>                 if (!odp_timeout_fresh(tmo))
>                         CU_FAIL("Wrong status (stale) for fresh timeout");
>                 /* Fresh timeout => local timer must have matching tick */
> -               if (ttp->tick != tick) {
> -                       printf("Wrong tick: expected %"PRIu64" actual
> %"PRIu64"\n",
> -                              ttp->tick, tick);
> +               if (ttp != NULL && ttp->tick != tick) {
> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
> %"PRIu64"\n",
> +                               ttp->tick, tick);
>                         CU_FAIL("odp_timeout_tick() wrong tick");
>                 }
>                 /* Check that timeout was delivered 'timely' */
>                 if (tick > odp_timer_current_tick(tp))
>                         CU_FAIL("Timeout delivered early");
>                 if (tick < prev_tick) {
> -                       printf("Too late tick: %"PRIu64" prev_tick
> %"PRIu64"\n",
> -                              tick, prev_tick);
> -                       CU_FAIL("Timeout delivered late");
> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
> %"PRIu64"\n",
> +                               tick, prev_tick);
> +                       /* We don't report late timeouts using CU_FAIL */
> +                       odp_atomic_inc_u32(&ndelivtoolate);
>                 }
>         }
>
> -       /* Use assert() for correctness check of test program itself */
> -       assert(ttp->buf == ODP_BUFFER_INVALID);
> -       ttp->buf = buf;
> +       if (ttp != NULL) {
> +               /* Internal error */
> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
> +               ttp->buf = buf;
> +       }
>  }
>
>  /* @private Worker thread entrypoint which performs timer
> alloc/set/cancel/free
> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>                         /* Save expected expiration tick */
>                         tt[i].tick = cur_tick + tck;
>                 }
> -               if (usleep(1000/*1ms*/) < 0)
> -                       perror("usleep"), abort();
> +               struct timespec ts;
> +               ts.tv_sec = 0;
> +               ts.tv_nsec = 1000000; /* 1ms */
> +               if (nanosleep(&ts, NULL) < 0)
> +                       perror("nanosleep"), abort();
>         }
>
>         /* Cancel and free all timers */
> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>                         CU_FAIL("odp_timer_free");
>         }
>
> -       printf("Thread %u: %u timers set\n", thr, nset);
> -       printf("Thread %u: %u timers reset\n", thr, nreset);
> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
> -       printf("Thread %u: %u timers reset/cancelled too late\n",
> -              thr, ntoolate);
> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
> -       printf("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
> -              thr, nstale);
> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
> +               thr, ntoolate);
> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
> +       LOG_DBG("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
> +               thr, nstale);
>
>         /* Delay some more to ensure timeouts for expired timers can be
>          * received */
> -       usleep(1000/*1ms*/);
> +       struct timespec ts;
> +       ts.tv_sec = 0;
> +       ts.tv_nsec = 1000000; /* 1ms */
> +       if (nanosleep(&ts, NULL) < 0)
> +               perror("nanosleep"), abort();
>         while (nstale != 0) {
>                 odp_buffer_t buf = odp_queue_deq(queue);
>                 if (buf != ODP_BUFFER_INVALID) {
> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>         if (buf != ODP_BUFFER_INVALID)
>                 CU_FAIL("Unexpected buffer received");
>
> -       printf("Thread %u: exiting\n", thr);
> +       LOG_DBG("Thread %u: exiting\n", thr);
>         return NULL;
>  }
>
> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>  {
>         odp_buffer_pool_param_t params;
>         odp_timer_pool_param_t tparam;
> -       /* This is a stressfull test - need to reserve some cpu cycles
> -        * @TODO move to test/performance */
> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
> +       /* Reserve at least one core for running other processes so the
> timer
> +        * test hopefully can run undisturbed and thus get better timing
> +        * results. */
> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
> +       /* On a single-CPU machine run at least one thread */
> +       if (num_workers < 1)
> +               num_workers = 1;
>
>         /* Create timeout buffer pools */
>         params.buf_size  = 0;
> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>         CU_ASSERT(tpinfo.param.res_ns == RES);
>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
> -       printf("Timer pool\n");
> -       printf("----------\n");
> -       printf("  name: %s\n", tpinfo.name);
> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
> -       printf("\n");
> -
> -       printf("#timers..: %u\n", NTIMERS);
> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> -       printf("\n");
> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
> +
> +       LOG_DBG("#timers..: %u\n", NTIMERS);
> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>
>         uint64_t tick;
>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>         /* Initialize barrier used by worker threads for synchronization */
>         odp_barrier_init(&test_barrier, num_workers);
>
> +       /* Initialize the shared timeout counter */
> +       odp_atomic_init_u32(&ndelivtoolate, 0);
> +
>         /* Create and start worker threads */
>         pthrd_arg thrdarg;
>         thrdarg.testcase = 0;
> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>
>         /* Wait for worker threads to exit */
>         odp_cunit_thread_exit(&thrdarg);
> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
> +               odp_atomic_load_u32(&ndelivtoolate));
>
>         /* Check some statistics after the test */
>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
> --
> 1.9.1
>
>
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp
>
Anders Roxell Jan. 13, 2015, 11:27 p.m. | #2
On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
>
>
> On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:
>>
>> Don't report too late timeouts using CU_FAIL as this interferes with the
>> cunit
>> test framework. Just count and report (using LOG_DBG) the number of late
>> timeouts.
>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>> cunit
>> test framework.
>> Don't dereference pointer after successful check for NULL as this makes
>> Coverity
>> complain.
>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>> Use nanosleep instead of the deprecated usleep.
>>
>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>
>
> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>

May I suggest splitting this as a patch set?
one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.

Cheers,
Anders

>
>>
>> ---
>> (This document/code contribution attached is provided under the terms of
>> agreement LES-LTM-21309)
>>
>>  test/validation/odp_timer.c | 102
>> +++++++++++++++++++++++++-------------------
>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>
>> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
>> index 4c93f71..d893646 100644
>> --- a/test/validation/odp_timer.c
>> +++ b/test/validation/odp_timer.c
>> @@ -8,10 +8,13 @@
>>   * @file
>>   */
>>
>> -#include <assert.h>
>> +/* For rand_r and nanosleep */
>> +#define _POSIX_C_SOURCE 200112L
>> +#include <time.h>
>>  #include <unistd.h>
>>  #include <odp.h>
>>  #include "odp_cunit_common.h"
>> +#include "test_debug.h"
>>
>>  /** @private Timeout range in milliseconds (ms) */
>>  #define RANGE_MS 2000
>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>  /** @private Timer pool handle used by all threads */
>>  static odp_timer_pool_t tp;
>>
>> +/** @private Count of timeouts delivered too late */
>> +static odp_atomic_u32_t ndelivtoolate;
>> +
>>  /** @private min() function */
>>  static int min(int a, int b)
>>  {
>> @@ -47,8 +53,7 @@ struct test_timer {
>>  /* @private Handle a received (timeout) buffer */
>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t prev_tick)
>>  {
>> -       /* Use assert() for internal correctness checks of test program */
>> -       assert(buf != ODP_BUFFER_INVALID);
>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error */
>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>                 /* Not a timeout buffer */
>>                 CU_FAIL("Unexpected buffer type received");
>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool stale,
>> uint64_t prev_tick)
>>         if (ttp == NULL)
>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>
>> -       if (ttp->buf2 != buf)
>> +       if (ttp != NULL && ttp->buf2 != buf)
>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>> -       if (ttp->tim != tim)
>> +       if (ttp != NULL && ttp->tim != tim)
>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>         if (stale) {
>>                 if (odp_timeout_fresh(tmo))
>>                         CU_FAIL("Wrong status (fresh) for stale timeout");
>>                 /* Stale timeout => local timer must have invalid tick */
>> -               if (ttp->tick != TICK_INVALID)
>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>                         CU_FAIL("Stale timeout for active timer");
>>         } else {
>>                 if (!odp_timeout_fresh(tmo))
>>                         CU_FAIL("Wrong status (stale) for fresh timeout");
>>                 /* Fresh timeout => local timer must have matching tick */
>> -               if (ttp->tick != tick) {
>> -                       printf("Wrong tick: expected %"PRIu64" actual
>> %"PRIu64"\n",
>> -                              ttp->tick, tick);
>> +               if (ttp != NULL && ttp->tick != tick) {
>> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
>> %"PRIu64"\n",
>> +                               ttp->tick, tick);
>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>                 }
>>                 /* Check that timeout was delivered 'timely' */
>>                 if (tick > odp_timer_current_tick(tp))
>>                         CU_FAIL("Timeout delivered early");
>>                 if (tick < prev_tick) {
>> -                       printf("Too late tick: %"PRIu64" prev_tick
>> %"PRIu64"\n",
>> -                              tick, prev_tick);
>> -                       CU_FAIL("Timeout delivered late");
>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>> %"PRIu64"\n",
>> +                               tick, prev_tick);
>> +                       /* We don't report late timeouts using CU_FAIL */
>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>                 }
>>         }
>>
>> -       /* Use assert() for correctness check of test program itself */
>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>> -       ttp->buf = buf;
>> +       if (ttp != NULL) {
>> +               /* Internal error */
>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>> +               ttp->buf = buf;
>> +       }
>>  }
>>
>>  /* @private Worker thread entrypoint which performs timer
>> alloc/set/cancel/free
>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>                         /* Save expected expiration tick */
>>                         tt[i].tick = cur_tick + tck;
>>                 }
>> -               if (usleep(1000/*1ms*/) < 0)
>> -                       perror("usleep"), abort();
>> +               struct timespec ts;
>> +               ts.tv_sec = 0;
>> +               ts.tv_nsec = 1000000; /* 1ms */
>> +               if (nanosleep(&ts, NULL) < 0)
>> +                       perror("nanosleep"), abort();
>>         }
>>
>>         /* Cancel and free all timers */
>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>                         CU_FAIL("odp_timer_free");
>>         }
>>
>> -       printf("Thread %u: %u timers set\n", thr, nset);
>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>> -              thr, ntoolate);
>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>> -       printf("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
>> -              thr, nstale);
>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>> +               thr, ntoolate);
>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>> +       LOG_DBG("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
>> +               thr, nstale);
>>
>>         /* Delay some more to ensure timeouts for expired timers can be
>>          * received */
>> -       usleep(1000/*1ms*/);
>> +       struct timespec ts;
>> +       ts.tv_sec = 0;
>> +       ts.tv_nsec = 1000000; /* 1ms */
>> +       if (nanosleep(&ts, NULL) < 0)
>> +               perror("nanosleep"), abort();
>>         while (nstale != 0) {
>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>                 if (buf != ODP_BUFFER_INVALID) {
>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>         if (buf != ODP_BUFFER_INVALID)
>>                 CU_FAIL("Unexpected buffer received");
>>
>> -       printf("Thread %u: exiting\n", thr);
>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>         return NULL;
>>  }
>>
>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>  {
>>         odp_buffer_pool_param_t params;
>>         odp_timer_pool_param_t tparam;
>> -       /* This is a stressfull test - need to reserve some cpu cycles
>> -        * @TODO move to test/performance */
>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>> +       /* Reserve at least one core for running other processes so the
>> timer
>> +        * test hopefully can run undisturbed and thus get better timing
>> +        * results. */
>> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>> +       /* On a single-CPU machine run at least one thread */
>> +       if (num_workers < 1)
>> +               num_workers = 1;
>>
>>         /* Create timeout buffer pools */
>>         params.buf_size  = 0;
>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>> -       printf("Timer pool\n");
>> -       printf("----------\n");
>> -       printf("  name: %s\n", tpinfo.name);
>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>> -       printf("\n");
>> -
>> -       printf("#timers..: %u\n", NTIMERS);
>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>> -       printf("\n");
>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>> +
>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>
>>         uint64_t tick;
>>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>         /* Initialize barrier used by worker threads for synchronization
>> */
>>         odp_barrier_init(&test_barrier, num_workers);
>>
>> +       /* Initialize the shared timeout counter */
>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>> +
>>         /* Create and start worker threads */
>>         pthrd_arg thrdarg;
>>         thrdarg.testcase = 0;
>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>
>>         /* Wait for worker threads to exit */
>>         odp_cunit_thread_exit(&thrdarg);
>> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
>> +               odp_atomic_load_u32(&ndelivtoolate));
>>
>>         /* Check some statistics after the test */
>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>> --
>> 1.9.1
>>
>>
>> _______________________________________________
>> lng-odp mailing list
>> lng-odp@lists.linaro.org
>> http://lists.linaro.org/mailman/listinfo/lng-odp
>
>
>
>
> --
> Mike Holmes
> Linaro  Sr Technical Manager
> LNG - ODP
>
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp
>
Ola Liljedahl Jan. 14, 2015, 4:33 p.m. | #3
On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org> wrote:
> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
>>
>>
>> On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:
>>>
>>> Don't report too late timeouts using CU_FAIL as this interferes with the
>>> cunit
>>> test framework. Just count and report (using LOG_DBG) the number of late
>>> timeouts.
>>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>>> cunit
>>> test framework.
>>> Don't dereference pointer after successful check for NULL as this makes
>>> Coverity
>>> complain.
>>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>> Use nanosleep instead of the deprecated usleep.
>>>
>>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>
>>
>> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>
> May I suggest splitting this as a patch set?
> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
Much work for little gain.

>
> Cheers,
> Anders
>
>>
>>>
>>> ---
>>> (This document/code contribution attached is provided under the terms of
>>> agreement LES-LTM-21309)
>>>
>>>  test/validation/odp_timer.c | 102
>>> +++++++++++++++++++++++++-------------------
>>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>>
>>> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
>>> index 4c93f71..d893646 100644
>>> --- a/test/validation/odp_timer.c
>>> +++ b/test/validation/odp_timer.c
>>> @@ -8,10 +8,13 @@
>>>   * @file
>>>   */
>>>
>>> -#include <assert.h>
>>> +/* For rand_r and nanosleep */
>>> +#define _POSIX_C_SOURCE 200112L
>>> +#include <time.h>
>>>  #include <unistd.h>
>>>  #include <odp.h>
>>>  #include "odp_cunit_common.h"
>>> +#include "test_debug.h"
>>>
>>>  /** @private Timeout range in milliseconds (ms) */
>>>  #define RANGE_MS 2000
>>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>  /** @private Timer pool handle used by all threads */
>>>  static odp_timer_pool_t tp;
>>>
>>> +/** @private Count of timeouts delivered too late */
>>> +static odp_atomic_u32_t ndelivtoolate;
>>> +
>>>  /** @private min() function */
>>>  static int min(int a, int b)
>>>  {
>>> @@ -47,8 +53,7 @@ struct test_timer {
>>>  /* @private Handle a received (timeout) buffer */
>>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t prev_tick)
>>>  {
>>> -       /* Use assert() for internal correctness checks of test program */
>>> -       assert(buf != ODP_BUFFER_INVALID);
>>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error */
>>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>                 /* Not a timeout buffer */
>>>                 CU_FAIL("Unexpected buffer type received");
>>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool stale,
>>> uint64_t prev_tick)
>>>         if (ttp == NULL)
>>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>
>>> -       if (ttp->buf2 != buf)
>>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>> -       if (ttp->tim != tim)
>>> +       if (ttp != NULL && ttp->tim != tim)
>>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>>         if (stale) {
>>>                 if (odp_timeout_fresh(tmo))
>>>                         CU_FAIL("Wrong status (fresh) for stale timeout");
>>>                 /* Stale timeout => local timer must have invalid tick */
>>> -               if (ttp->tick != TICK_INVALID)
>>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>                         CU_FAIL("Stale timeout for active timer");
>>>         } else {
>>>                 if (!odp_timeout_fresh(tmo))
>>>                         CU_FAIL("Wrong status (stale) for fresh timeout");
>>>                 /* Fresh timeout => local timer must have matching tick */
>>> -               if (ttp->tick != tick) {
>>> -                       printf("Wrong tick: expected %"PRIu64" actual
>>> %"PRIu64"\n",
>>> -                              ttp->tick, tick);
>>> +               if (ttp != NULL && ttp->tick != tick) {
>>> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
>>> %"PRIu64"\n",
>>> +                               ttp->tick, tick);
>>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>>                 }
>>>                 /* Check that timeout was delivered 'timely' */
>>>                 if (tick > odp_timer_current_tick(tp))
>>>                         CU_FAIL("Timeout delivered early");
>>>                 if (tick < prev_tick) {
>>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>> %"PRIu64"\n",
>>> -                              tick, prev_tick);
>>> -                       CU_FAIL("Timeout delivered late");
>>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>> %"PRIu64"\n",
>>> +                               tick, prev_tick);
>>> +                       /* We don't report late timeouts using CU_FAIL */
>>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>                 }
>>>         }
>>>
>>> -       /* Use assert() for correctness check of test program itself */
>>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>> -       ttp->buf = buf;
>>> +       if (ttp != NULL) {
>>> +               /* Internal error */
>>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>> +               ttp->buf = buf;
>>> +       }
>>>  }
>>>
>>>  /* @private Worker thread entrypoint which performs timer
>>> alloc/set/cancel/free
>>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>                         /* Save expected expiration tick */
>>>                         tt[i].tick = cur_tick + tck;
>>>                 }
>>> -               if (usleep(1000/*1ms*/) < 0)
>>> -                       perror("usleep"), abort();
>>> +               struct timespec ts;
>>> +               ts.tv_sec = 0;
>>> +               ts.tv_nsec = 1000000; /* 1ms */
>>> +               if (nanosleep(&ts, NULL) < 0)
>>> +                       perror("nanosleep"), abort();
>>>         }
>>>
>>>         /* Cancel and free all timers */
>>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>                         CU_FAIL("odp_timer_free");
>>>         }
>>>
>>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>> -              thr, ntoolate);
>>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>> -       printf("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
>>> -              thr, nstale);
>>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>> +               thr, ntoolate);
>>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>> +       LOG_DBG("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
>>> +               thr, nstale);
>>>
>>>         /* Delay some more to ensure timeouts for expired timers can be
>>>          * received */
>>> -       usleep(1000/*1ms*/);
>>> +       struct timespec ts;
>>> +       ts.tv_sec = 0;
>>> +       ts.tv_nsec = 1000000; /* 1ms */
>>> +       if (nanosleep(&ts, NULL) < 0)
>>> +               perror("nanosleep"), abort();
>>>         while (nstale != 0) {
>>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>>                 if (buf != ODP_BUFFER_INVALID) {
>>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>         if (buf != ODP_BUFFER_INVALID)
>>>                 CU_FAIL("Unexpected buffer received");
>>>
>>> -       printf("Thread %u: exiting\n", thr);
>>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>         return NULL;
>>>  }
>>>
>>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>  {
>>>         odp_buffer_pool_param_t params;
>>>         odp_timer_pool_param_t tparam;
>>> -       /* This is a stressfull test - need to reserve some cpu cycles
>>> -        * @TODO move to test/performance */
>>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>> +       /* Reserve at least one core for running other processes so the
>>> timer
>>> +        * test hopefully can run undisturbed and thus get better timing
>>> +        * results. */
>>> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>>> +       /* On a single-CPU machine run at least one thread */
>>> +       if (num_workers < 1)
>>> +               num_workers = 1;
>>>
>>>         /* Create timeout buffer pools */
>>>         params.buf_size  = 0;
>>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>> -       printf("Timer pool\n");
>>> -       printf("----------\n");
>>> -       printf("  name: %s\n", tpinfo.name);
>>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>> -       printf("\n");
>>> -
>>> -       printf("#timers..: %u\n", NTIMERS);
>>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>> -       printf("\n");
>>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>> +
>>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>
>>>         uint64_t tick;
>>>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
>>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>         /* Initialize barrier used by worker threads for synchronization
>>> */
>>>         odp_barrier_init(&test_barrier, num_workers);
>>>
>>> +       /* Initialize the shared timeout counter */
>>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>> +
>>>         /* Create and start worker threads */
>>>         pthrd_arg thrdarg;
>>>         thrdarg.testcase = 0;
>>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>
>>>         /* Wait for worker threads to exit */
>>>         odp_cunit_thread_exit(&thrdarg);
>>> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
>>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>
>>>         /* Check some statistics after the test */
>>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>> --
>>> 1.9.1
>>>
>>>
>>> _______________________________________________
>>> lng-odp mailing list
>>> lng-odp@lists.linaro.org
>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>
>>
>>
>>
>> --
>> Mike Holmes
>> Linaro  Sr Technical Manager
>> LNG - ODP
>>
>> _______________________________________________
>> lng-odp mailing list
>> lng-odp@lists.linaro.org
>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>
Bill Fischofer Jan. 14, 2015, 5:36 p.m. | #4
I think the question of how patches are modularized depends on what the
purpose of the patch is.  We can distinguish between a "Type 1" patch,
which represents a change that is intended to be accepted or rejected as a
whole, and a "Type 2" patch, which is designed to present a set of
selectable features that others may cherry-pick from in building their own
distribution.

The tension we seem to have is that virtually all ODP patches at this stage
in its history are Type 1 patches, whereas virtually all of the patches
associated with things like the Linux kernel are Type 2.  While is is not
incorrect to use a Type 2 structure for a Type 1 purpose, the benefits of
this level of modularity are diminished.  This is because the purpose of
modularity in a Type 1 patch is simply to facilitate its timely review and
acceptance.  Indeed, overly-modular patches may inhibit this purpose
because a proper review must confirm the implied orthogonality of the
modules, even if they are never intended to be separated.

So it would seem that Type 1 patches should be sufficiently modular to
allow for easy review but we need not be overly concerned with
orthogonality, as the "parts" par there for review convenience, and are not
there to imply that the author intents them to be separable.





On Wed, Jan 14, 2015 at 10:33 AM, Ola Liljedahl <ola.liljedahl@linaro.org>
wrote:

> On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org>
> wrote:
> > On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
> >>
> >>
> >> On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
> wrote:
> >>>
> >>> Don't report too late timeouts using CU_FAIL as this interferes with
> the
> >>> cunit
> >>> test framework. Just count and report (using LOG_DBG) the number of
> late
> >>> timeouts.
> >>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
> >>> cunit
> >>> test framework.
> >>> Don't dereference pointer after successful check for NULL as this makes
> >>> Coverity
> >>> complain.
> >>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> >>> Use nanosleep instead of the deprecated usleep.
> >>>
> >>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
> >>
> >>
> >> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
> >
> > May I suggest splitting this as a patch set?
> > one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
> Much work for little gain.
>
> >
> > Cheers,
> > Anders
> >
> >>
> >>>
> >>> ---
> >>> (This document/code contribution attached is provided under the terms
> of
> >>> agreement LES-LTM-21309)
> >>>
> >>>  test/validation/odp_timer.c | 102
> >>> +++++++++++++++++++++++++-------------------
> >>>  1 file changed, 59 insertions(+), 43 deletions(-)
> >>>
> >>> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
> >>> index 4c93f71..d893646 100644
> >>> --- a/test/validation/odp_timer.c
> >>> +++ b/test/validation/odp_timer.c
> >>> @@ -8,10 +8,13 @@
> >>>   * @file
> >>>   */
> >>>
> >>> -#include <assert.h>
> >>> +/* For rand_r and nanosleep */
> >>> +#define _POSIX_C_SOURCE 200112L
> >>> +#include <time.h>
> >>>  #include <unistd.h>
> >>>  #include <odp.h>
> >>>  #include "odp_cunit_common.h"
> >>> +#include "test_debug.h"
> >>>
> >>>  /** @private Timeout range in milliseconds (ms) */
> >>>  #define RANGE_MS 2000
> >>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
> >>>  /** @private Timer pool handle used by all threads */
> >>>  static odp_timer_pool_t tp;
> >>>
> >>> +/** @private Count of timeouts delivered too late */
> >>> +static odp_atomic_u32_t ndelivtoolate;
> >>> +
> >>>  /** @private min() function */
> >>>  static int min(int a, int b)
> >>>  {
> >>> @@ -47,8 +53,7 @@ struct test_timer {
> >>>  /* @private Handle a received (timeout) buffer */
> >>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
> prev_tick)
> >>>  {
> >>> -       /* Use assert() for internal correctness checks of test
> program */
> >>> -       assert(buf != ODP_BUFFER_INVALID);
> >>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error
> */
> >>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
> >>>                 /* Not a timeout buffer */
> >>>                 CU_FAIL("Unexpected buffer type received");
> >>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
> stale,
> >>> uint64_t prev_tick)
> >>>         if (ttp == NULL)
> >>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
> >>>
> >>> -       if (ttp->buf2 != buf)
> >>> +       if (ttp != NULL && ttp->buf2 != buf)
> >>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
> >>> -       if (ttp->tim != tim)
> >>> +       if (ttp != NULL && ttp->tim != tim)
> >>>                 CU_FAIL("odp_timeout_timer() wrong timer");
> >>>         if (stale) {
> >>>                 if (odp_timeout_fresh(tmo))
> >>>                         CU_FAIL("Wrong status (fresh) for stale
> timeout");
> >>>                 /* Stale timeout => local timer must have invalid tick
> */
> >>> -               if (ttp->tick != TICK_INVALID)
> >>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
> >>>                         CU_FAIL("Stale timeout for active timer");
> >>>         } else {
> >>>                 if (!odp_timeout_fresh(tmo))
> >>>                         CU_FAIL("Wrong status (stale) for fresh
> timeout");
> >>>                 /* Fresh timeout => local timer must have matching
> tick */
> >>> -               if (ttp->tick != tick) {
> >>> -                       printf("Wrong tick: expected %"PRIu64" actual
> >>> %"PRIu64"\n",
> >>> -                              ttp->tick, tick);
> >>> +               if (ttp != NULL && ttp->tick != tick) {
> >>> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
> >>> %"PRIu64"\n",
> >>> +                               ttp->tick, tick);
> >>>                         CU_FAIL("odp_timeout_tick() wrong tick");
> >>>                 }
> >>>                 /* Check that timeout was delivered 'timely' */
> >>>                 if (tick > odp_timer_current_tick(tp))
> >>>                         CU_FAIL("Timeout delivered early");
> >>>                 if (tick < prev_tick) {
> >>> -                       printf("Too late tick: %"PRIu64" prev_tick
> >>> %"PRIu64"\n",
> >>> -                              tick, prev_tick);
> >>> -                       CU_FAIL("Timeout delivered late");
> >>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
> >>> %"PRIu64"\n",
> >>> +                               tick, prev_tick);
> >>> +                       /* We don't report late timeouts using CU_FAIL
> */
> >>> +                       odp_atomic_inc_u32(&ndelivtoolate);
> >>>                 }
> >>>         }
> >>>
> >>> -       /* Use assert() for correctness check of test program itself */
> >>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
> >>> -       ttp->buf = buf;
> >>> +       if (ttp != NULL) {
> >>> +               /* Internal error */
> >>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
> >>> +               ttp->buf = buf;
> >>> +       }
> >>>  }
> >>>
> >>>  /* @private Worker thread entrypoint which performs timer
> >>> alloc/set/cancel/free
> >>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
> >>>                         /* Save expected expiration tick */
> >>>                         tt[i].tick = cur_tick + tck;
> >>>                 }
> >>> -               if (usleep(1000/*1ms*/) < 0)
> >>> -                       perror("usleep"), abort();
> >>> +               struct timespec ts;
> >>> +               ts.tv_sec = 0;
> >>> +               ts.tv_nsec = 1000000; /* 1ms */
> >>> +               if (nanosleep(&ts, NULL) < 0)
> >>> +                       perror("nanosleep"), abort();
> >>>         }
> >>>
> >>>         /* Cancel and free all timers */
> >>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
> >>>                         CU_FAIL("odp_timer_free");
> >>>         }
> >>>
> >>> -       printf("Thread %u: %u timers set\n", thr, nset);
> >>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
> >>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
> >>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
> >>> -              thr, ntoolate);
> >>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
> >>> -       printf("Thread %u: %u stale timeout(s) after
> odp_timer_free()\n",
> >>> -              thr, nstale);
> >>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
> >>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
> >>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
> >>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
> >>> +               thr, ntoolate);
> >>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
> >>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
> odp_timer_free()\n",
> >>> +               thr, nstale);
> >>>
> >>>         /* Delay some more to ensure timeouts for expired timers can be
> >>>          * received */
> >>> -       usleep(1000/*1ms*/);
> >>> +       struct timespec ts;
> >>> +       ts.tv_sec = 0;
> >>> +       ts.tv_nsec = 1000000; /* 1ms */
> >>> +       if (nanosleep(&ts, NULL) < 0)
> >>> +               perror("nanosleep"), abort();
> >>>         while (nstale != 0) {
> >>>                 odp_buffer_t buf = odp_queue_deq(queue);
> >>>                 if (buf != ODP_BUFFER_INVALID) {
> >>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
> >>>         if (buf != ODP_BUFFER_INVALID)
> >>>                 CU_FAIL("Unexpected buffer received");
> >>>
> >>> -       printf("Thread %u: exiting\n", thr);
> >>> +       LOG_DBG("Thread %u: exiting\n", thr);
> >>>         return NULL;
> >>>  }
> >>>
> >>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
> >>>  {
> >>>         odp_buffer_pool_param_t params;
> >>>         odp_timer_pool_param_t tparam;
> >>> -       /* This is a stressfull test - need to reserve some cpu cycles
> >>> -        * @TODO move to test/performance */
> >>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
> >>> +       /* Reserve at least one core for running other processes so the
> >>> timer
> >>> +        * test hopefully can run undisturbed and thus get better
> timing
> >>> +        * results. */
> >>> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
> >>> +       /* On a single-CPU machine run at least one thread */
> >>> +       if (num_workers < 1)
> >>> +               num_workers = 1;
> >>>
> >>>         /* Create timeout buffer pools */
> >>>         params.buf_size  = 0;
> >>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
> >>>         CU_ASSERT(tpinfo.param.res_ns == RES);
> >>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
> >>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
> >>> -       printf("Timer pool\n");
> >>> -       printf("----------\n");
> >>> -       printf("  name: %s\n", tpinfo.name);
> >>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
> >>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
> >>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
> >>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
> >>> -       printf("\n");
> >>> -
> >>> -       printf("#timers..: %u\n", NTIMERS);
> >>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >>> -       printf("\n");
> >>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
> >>> +
> >>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
> >>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >>>
> >>>         uint64_t tick;
> >>>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
> >>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
> >>>         /* Initialize barrier used by worker threads for
> synchronization
> >>> */
> >>>         odp_barrier_init(&test_barrier, num_workers);
> >>>
> >>> +       /* Initialize the shared timeout counter */
> >>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
> >>> +
> >>>         /* Create and start worker threads */
> >>>         pthrd_arg thrdarg;
> >>>         thrdarg.testcase = 0;
> >>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
> >>>
> >>>         /* Wait for worker threads to exit */
> >>>         odp_cunit_thread_exit(&thrdarg);
> >>> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
> >>> +               odp_atomic_load_u32(&ndelivtoolate));
> >>>
> >>>         /* Check some statistics after the test */
> >>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
> >>> --
> >>> 1.9.1
> >>>
> >>>
> >>> _______________________________________________
> >>> lng-odp mailing list
> >>> lng-odp@lists.linaro.org
> >>> http://lists.linaro.org/mailman/listinfo/lng-odp
> >>
> >>
> >>
> >>
> >> --
> >> Mike Holmes
> >> Linaro  Sr Technical Manager
> >> LNG - ODP
> >>
> >> _______________________________________________
> >> lng-odp mailing list
> >> lng-odp@lists.linaro.org
> >> http://lists.linaro.org/mailman/listinfo/lng-odp
> >>
>
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp
>
Bill Fischofer Jan. 14, 2015, 7:53 p.m. | #5
It depends on what one considers the "problem" being solved.  "Cleanup
module X to reflect new API changes" could be argued is a single problem
even if it changes six lines of code that in theory could be six different
1-line patches.

The question is whether it would ever be reasonable to apply these
separately, or whether it really is simpler to review six patches rather
than one?

On Wed, Jan 14, 2015 at 1:45 PM, Ola Dahl <dahl.ola@gmail.com> wrote:

> Perhaps it suffices to say, as done here:
>
> https://www.kernel.org/doc/Documentation/SubmittingPatches
>
> that one should "Solve only one problem per patch."
>
> I think it is difficult to argue what the benefits would be of breaking
> this (perhaps trivial) rule ;-)
>
> Best regards,
>
> Ola D
>
>
> On Wed Jan 14 2015 at 6:37:38 PM Bill Fischofer <bill.fischofer@linaro.org>
> wrote:
>
>> I think the question of how patches are modularized depends on what the
>> purpose of the patch is.  We can distinguish between a "Type 1" patch,
>> which represents a change that is intended to be accepted or rejected as a
>> whole, and a "Type 2" patch, which is designed to present a set of
>> selectable features that others may cherry-pick from in building their own
>> distribution.
>>
>> The tension we seem to have is that virtually all ODP patches at this
>> stage in its history are Type 1 patches, whereas virtually all of the
>> patches associated with things like the Linux kernel are Type 2.  While is
>> is not incorrect to use a Type 2 structure for a Type 1 purpose, the
>> benefits of this level of modularity are diminished.  This is because the
>> purpose of modularity in a Type 1 patch is simply to facilitate its timely
>> review and acceptance.  Indeed, overly-modular patches may inhibit this
>> purpose because a proper review must confirm the implied orthogonality of
>> the modules, even if they are never intended to be separated.
>>
>> So it would seem that Type 1 patches should be sufficiently modular to
>> allow for easy review but we need not be overly concerned with
>> orthogonality, as the "parts" par there for review convenience, and are not
>> there to imply that the author intents them to be separable.
>>
>>
>>
>>
>>
>> On Wed, Jan 14, 2015 at 10:33 AM, Ola Liljedahl <ola.liljedahl@linaro.org
>> > wrote:
>>
>>> On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org>
>>> wrote:
>>> > On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>> wrote:
>>> >>
>>> >>
>>> >> On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
>>> wrote:
>>> >>>
>>> >>> Don't report too late timeouts using CU_FAIL as this interferes with
>>> the
>>> >>> cunit
>>> >>> test framework. Just count and report (using LOG_DBG) the number of
>>> late
>>> >>> timeouts.
>>> >>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>>> the
>>> >>> cunit
>>> >>> test framework.
>>> >>> Don't dereference pointer after successful check for NULL as this
>>> makes
>>> >>> Coverity
>>> >>> complain.
>>> >>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>> >>> Use nanosleep instead of the deprecated usleep.
>>> >>>
>>> >>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>> >>
>>> >>
>>> >> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>> >
>>> > May I suggest splitting this as a patch set?
>>> > one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
>>> Much work for little gain.
>>>
>>> >
>>> > Cheers,
>>> > Anders
>>> >
>>> >>
>>> >>>
>>> >>> ---
>>> >>> (This document/code contribution attached is provided under the
>>> terms of
>>> >>> agreement LES-LTM-21309)
>>> >>>
>>> >>>  test/validation/odp_timer.c | 102
>>> >>> +++++++++++++++++++++++++-------------------
>>> >>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>> >>>
>>> >>> diff --git a/test/validation/odp_timer.c
>>> b/test/validation/odp_timer.c
>>> >>> index 4c93f71..d893646 100644
>>> >>> --- a/test/validation/odp_timer.c
>>> >>> +++ b/test/validation/odp_timer.c
>>> >>> @@ -8,10 +8,13 @@
>>> >>>   * @file
>>> >>>   */
>>> >>>
>>> >>> -#include <assert.h>
>>> >>> +/* For rand_r and nanosleep */
>>> >>> +#define _POSIX_C_SOURCE 200112L
>>> >>> +#include <time.h>
>>> >>>  #include <unistd.h>
>>> >>>  #include <odp.h>
>>> >>>  #include "odp_cunit_common.h"
>>> >>> +#include "test_debug.h"
>>> >>>
>>> >>>  /** @private Timeout range in milliseconds (ms) */
>>> >>>  #define RANGE_MS 2000
>>> >>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>> >>>  /** @private Timer pool handle used by all threads */
>>> >>>  static odp_timer_pool_t tp;
>>> >>>
>>> >>> +/** @private Count of timeouts delivered too late */
>>> >>> +static odp_atomic_u32_t ndelivtoolate;
>>> >>> +
>>> >>>  /** @private min() function */
>>> >>>  static int min(int a, int b)
>>> >>>  {
>>> >>> @@ -47,8 +53,7 @@ struct test_timer {
>>> >>>  /* @private Handle a received (timeout) buffer */
>>> >>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>> prev_tick)
>>> >>>  {
>>> >>> -       /* Use assert() for internal correctness checks of test
>>> program */
>>> >>> -       assert(buf != ODP_BUFFER_INVALID);
>>> >>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>> error */
>>> >>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>> >>>                 /* Not a timeout buffer */
>>> >>>                 CU_FAIL("Unexpected buffer type received");
>>> >>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>> stale,
>>> >>> uint64_t prev_tick)
>>> >>>         if (ttp == NULL)
>>> >>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>> >>>
>>> >>> -       if (ttp->buf2 != buf)
>>> >>> +       if (ttp != NULL && ttp->buf2 != buf)
>>> >>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>> >>> -       if (ttp->tim != tim)
>>> >>> +       if (ttp != NULL && ttp->tim != tim)
>>> >>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>> >>>         if (stale) {
>>> >>>                 if (odp_timeout_fresh(tmo))
>>> >>>                         CU_FAIL("Wrong status (fresh) for stale
>>> timeout");
>>> >>>                 /* Stale timeout => local timer must have invalid
>>> tick */
>>> >>> -               if (ttp->tick != TICK_INVALID)
>>> >>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>> >>>                         CU_FAIL("Stale timeout for active timer");
>>> >>>         } else {
>>> >>>                 if (!odp_timeout_fresh(tmo))
>>> >>>                         CU_FAIL("Wrong status (stale) for fresh
>>> timeout");
>>> >>>                 /* Fresh timeout => local timer must have matching
>>> tick */
>>> >>> -               if (ttp->tick != tick) {
>>> >>> -                       printf("Wrong tick: expected %"PRIu64" actual
>>> >>> %"PRIu64"\n",
>>> >>> -                              ttp->tick, tick);
>>> >>> +               if (ttp != NULL && ttp->tick != tick) {
>>> >>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>> actual
>>> >>> %"PRIu64"\n",
>>> >>> +                               ttp->tick, tick);
>>> >>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>> >>>                 }
>>> >>>                 /* Check that timeout was delivered 'timely' */
>>> >>>                 if (tick > odp_timer_current_tick(tp))
>>> >>>                         CU_FAIL("Timeout delivered early");
>>> >>>                 if (tick < prev_tick) {
>>> >>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>> >>> %"PRIu64"\n",
>>> >>> -                              tick, prev_tick);
>>> >>> -                       CU_FAIL("Timeout delivered late");
>>> >>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>> >>> %"PRIu64"\n",
>>> >>> +                               tick, prev_tick);
>>> >>> +                       /* We don't report late timeouts using
>>> CU_FAIL */
>>> >>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>> >>>                 }
>>> >>>         }
>>> >>>
>>> >>> -       /* Use assert() for correctness check of test program itself
>>> */
>>> >>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>> >>> -       ttp->buf = buf;
>>> >>> +       if (ttp != NULL) {
>>> >>> +               /* Internal error */
>>> >>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>> >>> +               ttp->buf = buf;
>>> >>> +       }
>>> >>>  }
>>> >>>
>>> >>>  /* @private Worker thread entrypoint which performs timer
>>> >>> alloc/set/cancel/free
>>> >>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>> >>>                         /* Save expected expiration tick */
>>> >>>                         tt[i].tick = cur_tick + tck;
>>> >>>                 }
>>> >>> -               if (usleep(1000/*1ms*/) < 0)
>>> >>> -                       perror("usleep"), abort();
>>> >>> +               struct timespec ts;
>>> >>> +               ts.tv_sec = 0;
>>> >>> +               ts.tv_nsec = 1000000; /* 1ms */
>>> >>> +               if (nanosleep(&ts, NULL) < 0)
>>> >>> +                       perror("nanosleep"), abort();
>>> >>>         }
>>> >>>
>>> >>>         /* Cancel and free all timers */
>>> >>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>> >>>                         CU_FAIL("odp_timer_free");
>>> >>>         }
>>> >>>
>>> >>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>> >>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>> >>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> >>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>> >>> -              thr, ntoolate);
>>> >>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>> >>> -       printf("Thread %u: %u stale timeout(s) after
>>> odp_timer_free()\n",
>>> >>> -              thr, nstale);
>>> >>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>> >>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>> >>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> >>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>> >>> +               thr, ntoolate);
>>> >>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>> >>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>> odp_timer_free()\n",
>>> >>> +               thr, nstale);
>>> >>>
>>> >>>         /* Delay some more to ensure timeouts for expired timers can
>>> be
>>> >>>          * received */
>>> >>> -       usleep(1000/*1ms*/);
>>> >>> +       struct timespec ts;
>>> >>> +       ts.tv_sec = 0;
>>> >>> +       ts.tv_nsec = 1000000; /* 1ms */
>>> >>> +       if (nanosleep(&ts, NULL) < 0)
>>> >>> +               perror("nanosleep"), abort();
>>> >>>         while (nstale != 0) {
>>> >>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>> >>>                 if (buf != ODP_BUFFER_INVALID) {
>>> >>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>> >>>         if (buf != ODP_BUFFER_INVALID)
>>> >>>                 CU_FAIL("Unexpected buffer received");
>>> >>>
>>> >>> -       printf("Thread %u: exiting\n", thr);
>>> >>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>> >>>         return NULL;
>>> >>>  }
>>> >>>
>>> >>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>> >>>  {
>>> >>>         odp_buffer_pool_param_t params;
>>> >>>         odp_timer_pool_param_t tparam;
>>> >>> -       /* This is a stressfull test - need to reserve some cpu
>>> cycles
>>> >>> -        * @TODO move to test/performance */
>>> >>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>> >>> +       /* Reserve at least one core for running other processes so
>>> the
>>> >>> timer
>>> >>> +        * test hopefully can run undisturbed and thus get better
>>> timing
>>> >>> +        * results. */
>>> >>> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>>> >>> +       /* On a single-CPU machine run at least one thread */
>>> >>> +       if (num_workers < 1)
>>> >>> +               num_workers = 1;
>>> >>>
>>> >>>         /* Create timeout buffer pools */
>>> >>>         params.buf_size  = 0;
>>> >>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>> >>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>> >>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>> >>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>> >>> -       printf("Timer pool\n");
>>> >>> -       printf("----------\n");
>>> >>> -       printf("  name: %s\n", tpinfo.name);
>>> >>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>> >>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>> >>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>> >>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>> >>> -       printf("\n");
>>> >>> -
>>> >>> -       printf("#timers..: %u\n", NTIMERS);
>>> >>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> >>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>> >>> -       printf("\n");
>>> >>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>> >>> +
>>> >>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>> >>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> >>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>> >>>
>>> >>>         uint64_t tick;
>>> >>>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
>>> >>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>> >>>         /* Initialize barrier used by worker threads for
>>> synchronization
>>> >>> */
>>> >>>         odp_barrier_init(&test_barrier, num_workers);
>>> >>>
>>> >>> +       /* Initialize the shared timeout counter */
>>> >>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>> >>> +
>>> >>>         /* Create and start worker threads */
>>> >>>         pthrd_arg thrdarg;
>>> >>>         thrdarg.testcase = 0;
>>> >>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>> >>>
>>> >>>         /* Wait for worker threads to exit */
>>> >>>         odp_cunit_thread_exit(&thrdarg);
>>> >>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>> %u\n",
>>> >>> +               odp_atomic_load_u32(&ndelivtoolate));
>>> >>>
>>> >>>         /* Check some statistics after the test */
>>> >>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>> >>> --
>>> >>> 1.9.1
>>> >>>
>>> >>>
>>> >>> _______________________________________________
>>> >>> lng-odp mailing list
>>> >>> lng-odp@lists.linaro.org
>>> >>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>> >>
>>> >>
>>> >>
>>> >>
>>> >> --
>>> >> Mike Holmes
>>> >> Linaro  Sr Technical Manager
>>> >> LNG - ODP
>>> >>
>>> >> _______________________________________________
>>> >> lng-odp mailing list
>>> >> lng-odp@lists.linaro.org
>>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>>> >>
>>>
>>> _______________________________________________
>>> lng-odp mailing list
>>> lng-odp@lists.linaro.org
>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>
>>
>> _______________________________________________
>> lng-odp mailing list
>> lng-odp@lists.linaro.org
>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>
>
Mike Holmes Jan. 14, 2015, 8:21 p.m. | #6
On 14 January 2015 at 14:53, Bill Fischofer <bill.fischofer@linaro.org>
wrote:

> It depends on what one considers the "problem" being solved.  "Cleanup
> module X to reflect new API changes" could be argued is a single problem
> even if it changes six lines of code that in theory could be six different
> 1-line patches.
>
> The question is whether it would ever be reasonable to apply these
> separately, or whether it really is simpler to review six patches rather
> than one?
>

One point here is that the reviewer is just one user of the information - I
view it that a little effort by the submitter helps many more folk down the
road

The next  user of ODP is those who wish to know what changed when looking
at the git log as they upgrade, and more specific detail via more patches
can be helpful here.

The user after that is the system integrator who has to take the next
version of ODP and when he does this his whole test environment goes down,
he wants to automatically apply patches with a bisect tool because he knows
nothing about the code and does not want to. Good patch practice allows him
to know exactly what happened without him wading through many large
patches, a bisect will tell him quite accurately where the issue arose.
Bear in mind this guy might be using a product that in turn used ODP and he
is far from the source.

The final user is you, when 5 releases from now and many patches a bug is
found, the git log will clearly comment tightly on the area of interest
which hopefully correlates with the reported bug rather than being a change
buried inside and you have to hunt for it.

I am surprised there is any debate beyond a submitter haggling with a call
for a break up in a specific case.
I agree there are cases where it we may have reason to take something that
is not a good as we like, maybe there are good arguments such as time to
release etc but any compromise will run the risk of being cheap now and
expensive later.
In these cases, we the community need to chime in so that we find the
middle ground in a specific case, or we accept bribes and I can be bought
for about US $100 per decision :)


>
> On Wed, Jan 14, 2015 at 1:45 PM, Ola Dahl <dahl.ola@gmail.com> wrote:
>
>> Perhaps it suffices to say, as done here:
>>
>> https://www.kernel.org/doc/Documentation/SubmittingPatches
>>
>> that one should "Solve only one problem per patch."
>>
>> I think it is difficult to argue what the benefits would be of breaking
>> this (perhaps trivial) rule ;-)
>>
>> Best regards,
>>
>> Ola D
>>
>>
>> On Wed Jan 14 2015 at 6:37:38 PM Bill Fischofer <
>> bill.fischofer@linaro.org> wrote:
>>
>>> I think the question of how patches are modularized depends on what the
>>> purpose of the patch is.  We can distinguish between a "Type 1" patch,
>>> which represents a change that is intended to be accepted or rejected as a
>>> whole, and a "Type 2" patch, which is designed to present a set of
>>> selectable features that others may cherry-pick from in building their own
>>> distribution.
>>>
>>> The tension we seem to have is that virtually all ODP patches at this
>>> stage in its history are Type 1 patches, whereas virtually all of the
>>> patches associated with things like the Linux kernel are Type 2.  While is
>>> is not incorrect to use a Type 2 structure for a Type 1 purpose, the
>>> benefits of this level of modularity are diminished.  This is because the
>>> purpose of modularity in a Type 1 patch is simply to facilitate its timely
>>> review and acceptance.  Indeed, overly-modular patches may inhibit this
>>> purpose because a proper review must confirm the implied orthogonality of
>>> the modules, even if they are never intended to be separated.
>>>
>>> So it would seem that Type 1 patches should be sufficiently modular to
>>> allow for easy review but we need not be overly concerned with
>>> orthogonality, as the "parts" par there for review convenience, and are not
>>> there to imply that the author intents them to be separable.
>>>
>>>
>>>
>>>
>>>
>>> On Wed, Jan 14, 2015 at 10:33 AM, Ola Liljedahl <
>>> ola.liljedahl@linaro.org> wrote:
>>>
>>>> On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org>
>>>> wrote:
>>>> > On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>>> wrote:
>>>> >>
>>>> >>
>>>> >> On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
>>>> wrote:
>>>> >>>
>>>> >>> Don't report too late timeouts using CU_FAIL as this interferes
>>>> with the
>>>> >>> cunit
>>>> >>> test framework. Just count and report (using LOG_DBG) the number of
>>>> late
>>>> >>> timeouts.
>>>> >>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>>>> the
>>>> >>> cunit
>>>> >>> test framework.
>>>> >>> Don't dereference pointer after successful check for NULL as this
>>>> makes
>>>> >>> Coverity
>>>> >>> complain.
>>>> >>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>> >>> Use nanosleep instead of the deprecated usleep.
>>>> >>>
>>>> >>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>>> >>
>>>> >>
>>>> >> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>> >
>>>> > May I suggest splitting this as a patch set?
>>>> > one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>>>> few.
>>>> Much work for little gain.
>>>>
>>>> >
>>>> > Cheers,
>>>> > Anders
>>>> >
>>>> >>
>>>> >>>
>>>> >>> ---
>>>> >>> (This document/code contribution attached is provided under the
>>>> terms of
>>>> >>> agreement LES-LTM-21309)
>>>> >>>
>>>> >>>  test/validation/odp_timer.c | 102
>>>> >>> +++++++++++++++++++++++++-------------------
>>>> >>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>>> >>>
>>>> >>> diff --git a/test/validation/odp_timer.c
>>>> b/test/validation/odp_timer.c
>>>> >>> index 4c93f71..d893646 100644
>>>> >>> --- a/test/validation/odp_timer.c
>>>> >>> +++ b/test/validation/odp_timer.c
>>>> >>> @@ -8,10 +8,13 @@
>>>> >>>   * @file
>>>> >>>   */
>>>> >>>
>>>> >>> -#include <assert.h>
>>>> >>> +/* For rand_r and nanosleep */
>>>> >>> +#define _POSIX_C_SOURCE 200112L
>>>> >>> +#include <time.h>
>>>> >>>  #include <unistd.h>
>>>> >>>  #include <odp.h>
>>>> >>>  #include "odp_cunit_common.h"
>>>> >>> +#include "test_debug.h"
>>>> >>>
>>>> >>>  /** @private Timeout range in milliseconds (ms) */
>>>> >>>  #define RANGE_MS 2000
>>>> >>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>> >>>  /** @private Timer pool handle used by all threads */
>>>> >>>  static odp_timer_pool_t tp;
>>>> >>>
>>>> >>> +/** @private Count of timeouts delivered too late */
>>>> >>> +static odp_atomic_u32_t ndelivtoolate;
>>>> >>> +
>>>> >>>  /** @private min() function */
>>>> >>>  static int min(int a, int b)
>>>> >>>  {
>>>> >>> @@ -47,8 +53,7 @@ struct test_timer {
>>>> >>>  /* @private Handle a received (timeout) buffer */
>>>> >>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>>> prev_tick)
>>>> >>>  {
>>>> >>> -       /* Use assert() for internal correctness checks of test
>>>> program */
>>>> >>> -       assert(buf != ODP_BUFFER_INVALID);
>>>> >>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>>> error */
>>>> >>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>> >>>                 /* Not a timeout buffer */
>>>> >>>                 CU_FAIL("Unexpected buffer type received");
>>>> >>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>>> stale,
>>>> >>> uint64_t prev_tick)
>>>> >>>         if (ttp == NULL)
>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>> >>>
>>>> >>> -       if (ttp->buf2 != buf)
>>>> >>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>>> >>> -       if (ttp->tim != tim)
>>>> >>> +       if (ttp != NULL && ttp->tim != tim)
>>>> >>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>>> >>>         if (stale) {
>>>> >>>                 if (odp_timeout_fresh(tmo))
>>>> >>>                         CU_FAIL("Wrong status (fresh) for stale
>>>> timeout");
>>>> >>>                 /* Stale timeout => local timer must have invalid
>>>> tick */
>>>> >>> -               if (ttp->tick != TICK_INVALID)
>>>> >>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>> >>>                         CU_FAIL("Stale timeout for active timer");
>>>> >>>         } else {
>>>> >>>                 if (!odp_timeout_fresh(tmo))
>>>> >>>                         CU_FAIL("Wrong status (stale) for fresh
>>>> timeout");
>>>> >>>                 /* Fresh timeout => local timer must have matching
>>>> tick */
>>>> >>> -               if (ttp->tick != tick) {
>>>> >>> -                       printf("Wrong tick: expected %"PRIu64"
>>>> actual
>>>> >>> %"PRIu64"\n",
>>>> >>> -                              ttp->tick, tick);
>>>> >>> +               if (ttp != NULL && ttp->tick != tick) {
>>>> >>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>>> actual
>>>> >>> %"PRIu64"\n",
>>>> >>> +                               ttp->tick, tick);
>>>> >>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>>> >>>                 }
>>>> >>>                 /* Check that timeout was delivered 'timely' */
>>>> >>>                 if (tick > odp_timer_current_tick(tp))
>>>> >>>                         CU_FAIL("Timeout delivered early");
>>>> >>>                 if (tick < prev_tick) {
>>>> >>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>>> >>> %"PRIu64"\n",
>>>> >>> -                              tick, prev_tick);
>>>> >>> -                       CU_FAIL("Timeout delivered late");
>>>> >>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>>> >>> %"PRIu64"\n",
>>>> >>> +                               tick, prev_tick);
>>>> >>> +                       /* We don't report late timeouts using
>>>> CU_FAIL */
>>>> >>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>> >>>                 }
>>>> >>>         }
>>>> >>>
>>>> >>> -       /* Use assert() for correctness check of test program
>>>> itself */
>>>> >>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>>> >>> -       ttp->buf = buf;
>>>> >>> +       if (ttp != NULL) {
>>>> >>> +               /* Internal error */
>>>> >>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>>> >>> +               ttp->buf = buf;
>>>> >>> +       }
>>>> >>>  }
>>>> >>>
>>>> >>>  /* @private Worker thread entrypoint which performs timer
>>>> >>> alloc/set/cancel/free
>>>> >>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>> >>>                         /* Save expected expiration tick */
>>>> >>>                         tt[i].tick = cur_tick + tck;
>>>> >>>                 }
>>>> >>> -               if (usleep(1000/*1ms*/) < 0)
>>>> >>> -                       perror("usleep"), abort();
>>>> >>> +               struct timespec ts;
>>>> >>> +               ts.tv_sec = 0;
>>>> >>> +               ts.tv_nsec = 1000000; /* 1ms */
>>>> >>> +               if (nanosleep(&ts, NULL) < 0)
>>>> >>> +                       perror("nanosleep"), abort();
>>>> >>>         }
>>>> >>>
>>>> >>>         /* Cancel and free all timers */
>>>> >>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>> >>>                         CU_FAIL("odp_timer_free");
>>>> >>>         }
>>>> >>>
>>>> >>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>>> >>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>>> >>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>> >>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>>> >>> -              thr, ntoolate);
>>>> >>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>>> >>> -       printf("Thread %u: %u stale timeout(s) after
>>>> odp_timer_free()\n",
>>>> >>> -              thr, nstale);
>>>> >>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>>> >>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>>> >>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>> >>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>>> >>> +               thr, ntoolate);
>>>> >>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>>> >>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>>> odp_timer_free()\n",
>>>> >>> +               thr, nstale);
>>>> >>>
>>>> >>>         /* Delay some more to ensure timeouts for expired timers
>>>> can be
>>>> >>>          * received */
>>>> >>> -       usleep(1000/*1ms*/);
>>>> >>> +       struct timespec ts;
>>>> >>> +       ts.tv_sec = 0;
>>>> >>> +       ts.tv_nsec = 1000000; /* 1ms */
>>>> >>> +       if (nanosleep(&ts, NULL) < 0)
>>>> >>> +               perror("nanosleep"), abort();
>>>> >>>         while (nstale != 0) {
>>>> >>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>>> >>>                 if (buf != ODP_BUFFER_INVALID) {
>>>> >>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>> >>>         if (buf != ODP_BUFFER_INVALID)
>>>> >>>                 CU_FAIL("Unexpected buffer received");
>>>> >>>
>>>> >>> -       printf("Thread %u: exiting\n", thr);
>>>> >>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>> >>>         return NULL;
>>>> >>>  }
>>>> >>>
>>>> >>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>> >>>  {
>>>> >>>         odp_buffer_pool_param_t params;
>>>> >>>         odp_timer_pool_param_t tparam;
>>>> >>> -       /* This is a stressfull test - need to reserve some cpu
>>>> cycles
>>>> >>> -        * @TODO move to test/performance */
>>>> >>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>>> >>> +       /* Reserve at least one core for running other processes so
>>>> the
>>>> >>> timer
>>>> >>> +        * test hopefully can run undisturbed and thus get better
>>>> timing
>>>> >>> +        * results. */
>>>> >>> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>>>> >>> +       /* On a single-CPU machine run at least one thread */
>>>> >>> +       if (num_workers < 1)
>>>> >>> +               num_workers = 1;
>>>> >>>
>>>> >>>         /* Create timeout buffer pools */
>>>> >>>         params.buf_size  = 0;
>>>> >>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>> >>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>>> >>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>> >>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>>> >>> -       printf("Timer pool\n");
>>>> >>> -       printf("----------\n");
>>>> >>> -       printf("  name: %s\n", tpinfo.name);
>>>> >>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>>> >>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>>> >>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>>> >>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>>> >>> -       printf("\n");
>>>> >>> -
>>>> >>> -       printf("#timers..: %u\n", NTIMERS);
>>>> >>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>> >>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>> >>> -       printf("\n");
>>>> >>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>>> >>> +
>>>> >>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>>> >>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>> >>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>> >>>
>>>> >>>         uint64_t tick;
>>>> >>>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL)
>>>> {
>>>> >>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>> >>>         /* Initialize barrier used by worker threads for
>>>> synchronization
>>>> >>> */
>>>> >>>         odp_barrier_init(&test_barrier, num_workers);
>>>> >>>
>>>> >>> +       /* Initialize the shared timeout counter */
>>>> >>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>>> >>> +
>>>> >>>         /* Create and start worker threads */
>>>> >>>         pthrd_arg thrdarg;
>>>> >>>         thrdarg.testcase = 0;
>>>> >>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>> >>>
>>>> >>>         /* Wait for worker threads to exit */
>>>> >>>         odp_cunit_thread_exit(&thrdarg);
>>>> >>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>>> %u\n",
>>>> >>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>> >>>
>>>> >>>         /* Check some statistics after the test */
>>>> >>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>>> >>> --
>>>> >>> 1.9.1
>>>> >>>
>>>> >>>
>>>> >>> _______________________________________________
>>>> >>> lng-odp mailing list
>>>> >>> lng-odp@lists.linaro.org
>>>> >>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>> >>
>>>> >>
>>>> >>
>>>> >>
>>>> >> --
>>>> >> Mike Holmes
>>>> >> Linaro  Sr Technical Manager
>>>> >> LNG - ODP
>>>> >>
>>>> >> _______________________________________________
>>>> >> lng-odp mailing list
>>>> >> lng-odp@lists.linaro.org
>>>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>> >>
>>>>
>>>> _______________________________________________
>>>> lng-odp mailing list
>>>> lng-odp@lists.linaro.org
>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>
>>>
>>> _______________________________________________
>>> lng-odp mailing list
>>> lng-odp@lists.linaro.org
>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>
>>
>
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp
>
>
Bill Fischofer Jan. 14, 2015, 10:23 p.m. | #7
When a bug arises at some point in the future the question is finding the
bug and fixing it.  I cannot assume that the bug was ever explicitly
introduced by some patch.  It may be that someone is now using something in
a novel way that was always broken but never recognized as broken because
this specific combination of circumstances never arose before.

If I have some code that fails I first look at the code as it exists and
understand what is failing.  The history of how the code arrived at its
current state may be of some interest from a QA perspective, but do I
really care that this bug was three months old or three years old?  The
point is to fix the current code, not back out the last three years of
changes and then assume that a fix to that level is good enough.  So any
patch to fix the bug will be against the current code base, not against
some ancient patch that may well have been superseded many times in the
interim.

That is, unless you assume that there is no actual unified product and that
the product you're producing is in fact a patch stream that others will
assemble on an ad-hoc basis to create their own unique derived product of
their choosing. It seems to me that's the root issue here.  We're shipping
ODP v1.0, v1.1, etc, not a patch stream that others will cobble together
however they wish into something else.  Of course, as an open source
project people are free to use the code however they wish, but that's not
what's being supported by this group.  By definition, if you fork you
assume the support responsibility and costs of the derived work.

On Wed, Jan 14, 2015 at 2:21 PM, Mike Holmes <mike.holmes@linaro.org> wrote:

>
> On 14 January 2015 at 14:53, Bill Fischofer <bill.fischofer@linaro.org>
> wrote:
>
>> It depends on what one considers the "problem" being solved.  "Cleanup
>> module X to reflect new API changes" could be argued is a single problem
>> even if it changes six lines of code that in theory could be six different
>> 1-line patches.
>>
>> The question is whether it would ever be reasonable to apply these
>> separately, or whether it really is simpler to review six patches rather
>> than one?
>>
>
> One point here is that the reviewer is just one user of the information -
> I view it that a little effort by the submitter helps many more folk down
> the road
>
> The next  user of ODP is those who wish to know what changed when looking
> at the git log as they upgrade, and more specific detail via more patches
> can be helpful here.
>
> The user after that is the system integrator who has to take the next
> version of ODP and when he does this his whole test environment goes down,
> he wants to automatically apply patches with a bisect tool because he knows
> nothing about the code and does not want to. Good patch practice allows him
> to know exactly what happened without him wading through many large
> patches, a bisect will tell him quite accurately where the issue arose.
> Bear in mind this guy might be using a product that in turn used ODP and he
> is far from the source.
>
> The final user is you, when 5 releases from now and many patches a bug is
> found, the git log will clearly comment tightly on the area of interest
> which hopefully correlates with the reported bug rather than being a change
> buried inside and you have to hunt for it.
>
> I am surprised there is any debate beyond a submitter haggling with a call
> for a break up in a specific case.
> I agree there are cases where it we may have reason to take something that
> is not a good as we like, maybe there are good arguments such as time to
> release etc but any compromise will run the risk of being cheap now and
> expensive later.
> In these cases, we the community need to chime in so that we find the
> middle ground in a specific case, or we accept bribes and I can be bought
> for about US $100 per decision :)
>
>
>>
>> On Wed, Jan 14, 2015 at 1:45 PM, Ola Dahl <dahl.ola@gmail.com> wrote:
>>
>>> Perhaps it suffices to say, as done here:
>>>
>>> https://www.kernel.org/doc/Documentation/SubmittingPatches
>>>
>>> that one should "Solve only one problem per patch."
>>>
>>> I think it is difficult to argue what the benefits would be of breaking
>>> this (perhaps trivial) rule ;-)
>>>
>>> Best regards,
>>>
>>> Ola D
>>>
>>>
>>> On Wed Jan 14 2015 at 6:37:38 PM Bill Fischofer <
>>> bill.fischofer@linaro.org> wrote:
>>>
>>>> I think the question of how patches are modularized depends on what the
>>>> purpose of the patch is.  We can distinguish between a "Type 1" patch,
>>>> which represents a change that is intended to be accepted or rejected as a
>>>> whole, and a "Type 2" patch, which is designed to present a set of
>>>> selectable features that others may cherry-pick from in building their own
>>>> distribution.
>>>>
>>>> The tension we seem to have is that virtually all ODP patches at this
>>>> stage in its history are Type 1 patches, whereas virtually all of the
>>>> patches associated with things like the Linux kernel are Type 2.  While is
>>>> is not incorrect to use a Type 2 structure for a Type 1 purpose, the
>>>> benefits of this level of modularity are diminished.  This is because the
>>>> purpose of modularity in a Type 1 patch is simply to facilitate its timely
>>>> review and acceptance.  Indeed, overly-modular patches may inhibit this
>>>> purpose because a proper review must confirm the implied orthogonality of
>>>> the modules, even if they are never intended to be separated.
>>>>
>>>> So it would seem that Type 1 patches should be sufficiently modular to
>>>> allow for easy review but we need not be overly concerned with
>>>> orthogonality, as the "parts" par there for review convenience, and are not
>>>> there to imply that the author intents them to be separable.
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> On Wed, Jan 14, 2015 at 10:33 AM, Ola Liljedahl <
>>>> ola.liljedahl@linaro.org> wrote:
>>>>
>>>>> On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org>
>>>>> wrote:
>>>>> > On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>>>> wrote:
>>>>> >>
>>>>> >>
>>>>> >> On 12 January 2015 at 16:20, Ola Liljedahl <
>>>>> ola.liljedahl@linaro.org> wrote:
>>>>> >>>
>>>>> >>> Don't report too late timeouts using CU_FAIL as this interferes
>>>>> with the
>>>>> >>> cunit
>>>>> >>> test framework. Just count and report (using LOG_DBG) the number
>>>>> of late
>>>>> >>> timeouts.
>>>>> >>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>>>>> the
>>>>> >>> cunit
>>>>> >>> test framework.
>>>>> >>> Don't dereference pointer after successful check for NULL as this
>>>>> makes
>>>>> >>> Coverity
>>>>> >>> complain.
>>>>> >>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>> >>> Use nanosleep instead of the deprecated usleep.
>>>>> >>>
>>>>> >>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>>>> >>
>>>>> >>
>>>>> >> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>>> >
>>>>> > May I suggest splitting this as a patch set?
>>>>> > one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>>>>> few.
>>>>> Much work for little gain.
>>>>>
>>>>> >
>>>>> > Cheers,
>>>>> > Anders
>>>>> >
>>>>> >>
>>>>> >>>
>>>>> >>> ---
>>>>> >>> (This document/code contribution attached is provided under the
>>>>> terms of
>>>>> >>> agreement LES-LTM-21309)
>>>>> >>>
>>>>> >>>  test/validation/odp_timer.c | 102
>>>>> >>> +++++++++++++++++++++++++-------------------
>>>>> >>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>>>> >>>
>>>>> >>> diff --git a/test/validation/odp_timer.c
>>>>> b/test/validation/odp_timer.c
>>>>> >>> index 4c93f71..d893646 100644
>>>>> >>> --- a/test/validation/odp_timer.c
>>>>> >>> +++ b/test/validation/odp_timer.c
>>>>> >>> @@ -8,10 +8,13 @@
>>>>> >>>   * @file
>>>>> >>>   */
>>>>> >>>
>>>>> >>> -#include <assert.h>
>>>>> >>> +/* For rand_r and nanosleep */
>>>>> >>> +#define _POSIX_C_SOURCE 200112L
>>>>> >>> +#include <time.h>
>>>>> >>>  #include <unistd.h>
>>>>> >>>  #include <odp.h>
>>>>> >>>  #include "odp_cunit_common.h"
>>>>> >>> +#include "test_debug.h"
>>>>> >>>
>>>>> >>>  /** @private Timeout range in milliseconds (ms) */
>>>>> >>>  #define RANGE_MS 2000
>>>>> >>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>>> >>>  /** @private Timer pool handle used by all threads */
>>>>> >>>  static odp_timer_pool_t tp;
>>>>> >>>
>>>>> >>> +/** @private Count of timeouts delivered too late */
>>>>> >>> +static odp_atomic_u32_t ndelivtoolate;
>>>>> >>> +
>>>>> >>>  /** @private min() function */
>>>>> >>>  static int min(int a, int b)
>>>>> >>>  {
>>>>> >>> @@ -47,8 +53,7 @@ struct test_timer {
>>>>> >>>  /* @private Handle a received (timeout) buffer */
>>>>> >>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>>>> prev_tick)
>>>>> >>>  {
>>>>> >>> -       /* Use assert() for internal correctness checks of test
>>>>> program */
>>>>> >>> -       assert(buf != ODP_BUFFER_INVALID);
>>>>> >>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>>>> error */
>>>>> >>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>>> >>>                 /* Not a timeout buffer */
>>>>> >>>                 CU_FAIL("Unexpected buffer type received");
>>>>> >>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>>>> stale,
>>>>> >>> uint64_t prev_tick)
>>>>> >>>         if (ttp == NULL)
>>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>>> >>>
>>>>> >>> -       if (ttp->buf2 != buf)
>>>>> >>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>>>> >>> -       if (ttp->tim != tim)
>>>>> >>> +       if (ttp != NULL && ttp->tim != tim)
>>>>> >>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>>>> >>>         if (stale) {
>>>>> >>>                 if (odp_timeout_fresh(tmo))
>>>>> >>>                         CU_FAIL("Wrong status (fresh) for stale
>>>>> timeout");
>>>>> >>>                 /* Stale timeout => local timer must have invalid
>>>>> tick */
>>>>> >>> -               if (ttp->tick != TICK_INVALID)
>>>>> >>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>>> >>>                         CU_FAIL("Stale timeout for active timer");
>>>>> >>>         } else {
>>>>> >>>                 if (!odp_timeout_fresh(tmo))
>>>>> >>>                         CU_FAIL("Wrong status (stale) for fresh
>>>>> timeout");
>>>>> >>>                 /* Fresh timeout => local timer must have matching
>>>>> tick */
>>>>> >>> -               if (ttp->tick != tick) {
>>>>> >>> -                       printf("Wrong tick: expected %"PRIu64"
>>>>> actual
>>>>> >>> %"PRIu64"\n",
>>>>> >>> -                              ttp->tick, tick);
>>>>> >>> +               if (ttp != NULL && ttp->tick != tick) {
>>>>> >>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>>>> actual
>>>>> >>> %"PRIu64"\n",
>>>>> >>> +                               ttp->tick, tick);
>>>>> >>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>>>> >>>                 }
>>>>> >>>                 /* Check that timeout was delivered 'timely' */
>>>>> >>>                 if (tick > odp_timer_current_tick(tp))
>>>>> >>>                         CU_FAIL("Timeout delivered early");
>>>>> >>>                 if (tick < prev_tick) {
>>>>> >>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>>>> >>> %"PRIu64"\n",
>>>>> >>> -                              tick, prev_tick);
>>>>> >>> -                       CU_FAIL("Timeout delivered late");
>>>>> >>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>>>> >>> %"PRIu64"\n",
>>>>> >>> +                               tick, prev_tick);
>>>>> >>> +                       /* We don't report late timeouts using
>>>>> CU_FAIL */
>>>>> >>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>>> >>>                 }
>>>>> >>>         }
>>>>> >>>
>>>>> >>> -       /* Use assert() for correctness check of test program
>>>>> itself */
>>>>> >>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>>>> >>> -       ttp->buf = buf;
>>>>> >>> +       if (ttp != NULL) {
>>>>> >>> +               /* Internal error */
>>>>> >>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>>>> >>> +               ttp->buf = buf;
>>>>> >>> +       }
>>>>> >>>  }
>>>>> >>>
>>>>> >>>  /* @private Worker thread entrypoint which performs timer
>>>>> >>> alloc/set/cancel/free
>>>>> >>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>>> >>>                         /* Save expected expiration tick */
>>>>> >>>                         tt[i].tick = cur_tick + tck;
>>>>> >>>                 }
>>>>> >>> -               if (usleep(1000/*1ms*/) < 0)
>>>>> >>> -                       perror("usleep"), abort();
>>>>> >>> +               struct timespec ts;
>>>>> >>> +               ts.tv_sec = 0;
>>>>> >>> +               ts.tv_nsec = 1000000; /* 1ms */
>>>>> >>> +               if (nanosleep(&ts, NULL) < 0)
>>>>> >>> +                       perror("nanosleep"), abort();
>>>>> >>>         }
>>>>> >>>
>>>>> >>>         /* Cancel and free all timers */
>>>>> >>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>>> >>>                         CU_FAIL("odp_timer_free");
>>>>> >>>         }
>>>>> >>>
>>>>> >>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>>>> >>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>>>> >>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>> >>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>>>> >>> -              thr, ntoolate);
>>>>> >>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>> >>> -       printf("Thread %u: %u stale timeout(s) after
>>>>> odp_timer_free()\n",
>>>>> >>> -              thr, nstale);
>>>>> >>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>>>> >>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>>>> >>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>> >>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>>>> >>> +               thr, ntoolate);
>>>>> >>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>> >>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>>>> odp_timer_free()\n",
>>>>> >>> +               thr, nstale);
>>>>> >>>
>>>>> >>>         /* Delay some more to ensure timeouts for expired timers
>>>>> can be
>>>>> >>>          * received */
>>>>> >>> -       usleep(1000/*1ms*/);
>>>>> >>> +       struct timespec ts;
>>>>> >>> +       ts.tv_sec = 0;
>>>>> >>> +       ts.tv_nsec = 1000000; /* 1ms */
>>>>> >>> +       if (nanosleep(&ts, NULL) < 0)
>>>>> >>> +               perror("nanosleep"), abort();
>>>>> >>>         while (nstale != 0) {
>>>>> >>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>>>> >>>                 if (buf != ODP_BUFFER_INVALID) {
>>>>> >>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>>> >>>         if (buf != ODP_BUFFER_INVALID)
>>>>> >>>                 CU_FAIL("Unexpected buffer received");
>>>>> >>>
>>>>> >>> -       printf("Thread %u: exiting\n", thr);
>>>>> >>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>>> >>>         return NULL;
>>>>> >>>  }
>>>>> >>>
>>>>> >>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>>> >>>  {
>>>>> >>>         odp_buffer_pool_param_t params;
>>>>> >>>         odp_timer_pool_param_t tparam;
>>>>> >>> -       /* This is a stressfull test - need to reserve some cpu
>>>>> cycles
>>>>> >>> -        * @TODO move to test/performance */
>>>>> >>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>>>> >>> +       /* Reserve at least one core for running other processes
>>>>> so the
>>>>> >>> timer
>>>>> >>> +        * test hopefully can run undisturbed and thus get better
>>>>> timing
>>>>> >>> +        * results. */
>>>>> >>> +       int num_workers = min(odp_sys_cpu_count() - 1,
>>>>> MAX_WORKERS);
>>>>> >>> +       /* On a single-CPU machine run at least one thread */
>>>>> >>> +       if (num_workers < 1)
>>>>> >>> +               num_workers = 1;
>>>>> >>>
>>>>> >>>         /* Create timeout buffer pools */
>>>>> >>>         params.buf_size  = 0;
>>>>> >>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>>> >>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>>>> >>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>>> >>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>>>> >>> -       printf("Timer pool\n");
>>>>> >>> -       printf("----------\n");
>>>>> >>> -       printf("  name: %s\n", tpinfo.name);
>>>>> >>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>>>> >>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>>>> >>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>>>> >>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>>>> >>> -       printf("\n");
>>>>> >>> -
>>>>> >>> -       printf("#timers..: %u\n", NTIMERS);
>>>>> >>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>> >>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>> >>> -       printf("\n");
>>>>> >>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>>>> >>> +
>>>>> >>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>>>> >>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>> >>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>> >>>
>>>>> >>>         uint64_t tick;
>>>>> >>>         for (tick = 0; tick < 1000000000000ULL; tick +=
>>>>> 1000000ULL) {
>>>>> >>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>>> >>>         /* Initialize barrier used by worker threads for
>>>>> synchronization
>>>>> >>> */
>>>>> >>>         odp_barrier_init(&test_barrier, num_workers);
>>>>> >>>
>>>>> >>> +       /* Initialize the shared timeout counter */
>>>>> >>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>>>> >>> +
>>>>> >>>         /* Create and start worker threads */
>>>>> >>>         pthrd_arg thrdarg;
>>>>> >>>         thrdarg.testcase = 0;
>>>>> >>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>>> >>>
>>>>> >>>         /* Wait for worker threads to exit */
>>>>> >>>         odp_cunit_thread_exit(&thrdarg);
>>>>> >>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>>>> %u\n",
>>>>> >>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>>> >>>
>>>>> >>>         /* Check some statistics after the test */
>>>>> >>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>>>> >>> --
>>>>> >>> 1.9.1
>>>>> >>>
>>>>> >>>
>>>>> >>> _______________________________________________
>>>>> >>> lng-odp mailing list
>>>>> >>> lng-odp@lists.linaro.org
>>>>> >>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>> >>
>>>>> >>
>>>>> >>
>>>>> >>
>>>>> >> --
>>>>> >> Mike Holmes
>>>>> >> Linaro  Sr Technical Manager
>>>>> >> LNG - ODP
>>>>> >>
>>>>> >> _______________________________________________
>>>>> >> lng-odp mailing list
>>>>> >> lng-odp@lists.linaro.org
>>>>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>> >>
>>>>>
>>>>> _______________________________________________
>>>>> lng-odp mailing list
>>>>> lng-odp@lists.linaro.org
>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>
>>>>
>>>> _______________________________________________
>>>> lng-odp mailing list
>>>> lng-odp@lists.linaro.org
>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>
>>>
>>
>> _______________________________________________
>> lng-odp mailing list
>> lng-odp@lists.linaro.org
>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>
>>
>
>
> --
> *Mike Holmes*
> Linaro  Sr Technical Manager
> LNG - ODP
>
Bill Fischofer Jan. 14, 2015, 11:13 p.m. | #8
Thanks for the explanation of how git bisect is used.  However, while it
may aid in the understanding of the bug I still need to fix the current
code, not the 'bad' patch.  Otherwise I'm potentially faced with rebasing
all subsequent patches to work with the 'corrected' patch.

So the commit history will be:

c1, c2, ..., cBad, cBad+1, cBad+2 ... cLast

and what I need is cBadFix that applies to cLast, not to cBad.

Or is the open source tradition to try to apply cBadFix to cBad and then
deal with whatever ripple effects may occur in the subsequent patches?

On Wed, Jan 14, 2015 at 4:37 PM, Ola Dahl <dahl.ola@gmail.com> wrote:

> I try to reason, as follows:
>
> Suppose there is a bug
>
> Suppose also that to fix this bug, a number of lines have to be changed
>
> Some time, in the history of the project, theses lines were different from
> what they are now, or they did not exist.
>
> That time, when this happened, is defined by a commit
>
> That commit could be small, and well defined, or it could be large.
>
> And when finding that commit, I assume that git bisect could be useful,
> see e.g
>
> http://git-scm.com/docs/git-bisect
>
> for the purpose of finding in which commit the bug must have been
> introduced.
>
> And if the commit was not too large, the lines that we need to change in
> order to fix the bug would be easier to find than if the commit was very
> large.
>
> So I would therefore assume that a bug is always introduced in a patch
> (i.e. in a commit).
>
> And the history of the project is definitely interesting (and useful,
> since it is used by git bisect)
>
> Best regards,
>
> Ola D
>
>
> On Wed Jan 14 2015 at 11:23:44 PM Bill Fischofer <
> bill.fischofer@linaro.org> wrote:
>
>> When a bug arises at some point in the future the question is finding the
>> bug and fixing it.  I cannot assume that the bug was ever explicitly
>> introduced by some patch.  It may be that someone is now using something in
>> a novel way that was always broken but never recognized as broken because
>> this specific combination of circumstances never arose before.
>>
>> If I have some code that fails I first look at the code as it exists and
>> understand what is failing.  The history of how the code arrived at its
>> current state may be of some interest from a QA perspective, but do I
>> really care that this bug was three months old or three years old?  The
>> point is to fix the current code, not back out the last three years of
>> changes and then assume that a fix to that level is good enough.  So any
>> patch to fix the bug will be against the current code base, not against
>> some ancient patch that may well have been superseded many times in the
>> interim.
>>
>> That is, unless you assume that there is no actual unified product and
>> that the product you're producing is in fact a patch stream that others
>> will assemble on an ad-hoc basis to create their own unique derived product
>> of their choosing. It seems to me that's the root issue here.  We're
>> shipping ODP v1.0, v1.1, etc, not a patch stream that others will cobble
>> together however they wish into something else.  Of course, as an open
>> source project people are free to use the code however they wish, but
>> that's not what's being supported by this group.  By definition, if you
>> fork you assume the support responsibility and costs of the derived work.
>>
>> On Wed, Jan 14, 2015 at 2:21 PM, Mike Holmes <mike.holmes@linaro.org>
>> wrote:
>>
>>>
>>> On 14 January 2015 at 14:53, Bill Fischofer <bill.fischofer@linaro.org>
>>> wrote:
>>>
>>>> It depends on what one considers the "problem" being solved.  "Cleanup
>>>> module X to reflect new API changes" could be argued is a single problem
>>>> even if it changes six lines of code that in theory could be six different
>>>> 1-line patches.
>>>>
>>>> The question is whether it would ever be reasonable to apply these
>>>> separately, or whether it really is simpler to review six patches rather
>>>> than one?
>>>>
>>>
>>> One point here is that the reviewer is just one user of the information
>>> - I view it that a little effort by the submitter helps many more folk down
>>> the road
>>>
>>> The next  user of ODP is those who wish to know what changed when
>>> looking at the git log as they upgrade, and more specific detail via more
>>> patches can be helpful here.
>>>
>>> The user after that is the system integrator who has to take the next
>>> version of ODP and when he does this his whole test environment goes down,
>>> he wants to automatically apply patches with a bisect tool because he knows
>>> nothing about the code and does not want to. Good patch practice allows him
>>> to know exactly what happened without him wading through many large
>>> patches, a bisect will tell him quite accurately where the issue arose.
>>> Bear in mind this guy might be using a product that in turn used ODP and he
>>> is far from the source.
>>>
>>> The final user is you, when 5 releases from now and many patches a bug
>>> is found, the git log will clearly comment tightly on the area of interest
>>> which hopefully correlates with the reported bug rather than being a change
>>> buried inside and you have to hunt for it.
>>>
>>> I am surprised there is any debate beyond a submitter haggling with a
>>> call for a break up in a specific case.
>>> I agree there are cases where it we may have reason to take something
>>> that is not a good as we like, maybe there are good arguments such as time
>>> to release etc but any compromise will run the risk of being cheap now and
>>> expensive later.
>>> In these cases, we the community need to chime in so that we find the
>>> middle ground in a specific case, or we accept bribes and I can be bought
>>> for about US $100 per decision :)
>>>
>>>
>>>>
>>>> On Wed, Jan 14, 2015 at 1:45 PM, Ola Dahl <dahl.ola@gmail.com> wrote:
>>>>
>>>>> Perhaps it suffices to say, as done here:
>>>>>
>>>>> https://www.kernel.org/doc/Documentation/SubmittingPatches
>>>>>
>>>>> that one should "Solve only one problem per patch."
>>>>>
>>>>> I think it is difficult to argue what the benefits would be of
>>>>> breaking this (perhaps trivial) rule ;-)
>>>>>
>>>>> Best regards,
>>>>>
>>>>> Ola D
>>>>>
>>>>>
>>>>> On Wed Jan 14 2015 at 6:37:38 PM Bill Fischofer <
>>>>> bill.fischofer@linaro.org> wrote:
>>>>>
>>>>>> I think the question of how patches are modularized depends on what
>>>>>> the purpose of the patch is.  We can distinguish between a "Type 1" patch,
>>>>>> which represents a change that is intended to be accepted or rejected as a
>>>>>> whole, and a "Type 2" patch, which is designed to present a set of
>>>>>> selectable features that others may cherry-pick from in building their own
>>>>>> distribution.
>>>>>>
>>>>>> The tension we seem to have is that virtually all ODP patches at this
>>>>>> stage in its history are Type 1 patches, whereas virtually all of the
>>>>>> patches associated with things like the Linux kernel are Type 2.  While is
>>>>>> is not incorrect to use a Type 2 structure for a Type 1 purpose, the
>>>>>> benefits of this level of modularity are diminished.  This is because the
>>>>>> purpose of modularity in a Type 1 patch is simply to facilitate its timely
>>>>>> review and acceptance.  Indeed, overly-modular patches may inhibit this
>>>>>> purpose because a proper review must confirm the implied orthogonality of
>>>>>> the modules, even if they are never intended to be separated.
>>>>>>
>>>>>> So it would seem that Type 1 patches should be sufficiently modular
>>>>>> to allow for easy review but we need not be overly concerned with
>>>>>> orthogonality, as the "parts" par there for review convenience, and are not
>>>>>> there to imply that the author intents them to be separable.
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Wed, Jan 14, 2015 at 10:33 AM, Ola Liljedahl <
>>>>>> ola.liljedahl@linaro.org> wrote:
>>>>>>
>>>>>>> On 14 January 2015 at 00:27, Anders Roxell <anders.roxell@linaro.org>
>>>>>>> wrote:
>>>>>>> > On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>>>>>> wrote:
>>>>>>> >>
>>>>>>> >>
>>>>>>> >> On 12 January 2015 at 16:20, Ola Liljedahl <
>>>>>>> ola.liljedahl@linaro.org> wrote:
>>>>>>> >>>
>>>>>>> >>> Don't report too late timeouts using CU_FAIL as this interferes
>>>>>>> with the
>>>>>>> >>> cunit
>>>>>>> >>> test framework. Just count and report (using LOG_DBG) the number
>>>>>>> of late
>>>>>>> >>> timeouts.
>>>>>>> >>> Use CU_ASSERT_FATAL instead of plain assert so to work wither
>>>>>>> with the
>>>>>>> >>> cunit
>>>>>>> >>> test framework.
>>>>>>> >>> Don't dereference pointer after successful check for NULL as
>>>>>>> this makes
>>>>>>> >>> Coverity
>>>>>>> >>> complain.
>>>>>>> >>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>>>> >>> Use nanosleep instead of the deprecated usleep.
>>>>>>> >>>
>>>>>>> >>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>>>>>> >>
>>>>>>> >>
>>>>>>> >> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>>>>> >
>>>>>>> > May I suggest splitting this as a patch set?
>>>>>>> > one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>>>>>>> few.
>>>>>>> Much work for little gain.
>>>>>>>
>>>>>>> >
>>>>>>> > Cheers,
>>>>>>> > Anders
>>>>>>> >
>>>>>>> >>
>>>>>>> >>>
>>>>>>> >>> ---
>>>>>>> >>> (This document/code contribution attached is provided under the
>>>>>>> terms of
>>>>>>> >>> agreement LES-LTM-21309)
>>>>>>> >>>
>>>>>>> >>>  test/validation/odp_timer.c | 102
>>>>>>> >>> +++++++++++++++++++++++++-------------------
>>>>>>> >>>  1 file changed, 59 insertions(+), 43 deletions(-)
>>>>>>> >>>
>>>>>>> >>> diff --git a/test/validation/odp_timer.c
>>>>>>> b/test/validation/odp_timer.c
>>>>>>> >>> index 4c93f71..d893646 100644
>>>>>>> >>> --- a/test/validation/odp_timer.c
>>>>>>> >>> +++ b/test/validation/odp_timer.c
>>>>>>> >>> @@ -8,10 +8,13 @@
>>>>>>> >>>   * @file
>>>>>>> >>>   */
>>>>>>> >>>
>>>>>>> >>> -#include <assert.h>
>>>>>>> >>> +/* For rand_r and nanosleep */
>>>>>>> >>> +#define _POSIX_C_SOURCE 200112L
>>>>>>> >>> +#include <time.h>
>>>>>>> >>>  #include <unistd.h>
>>>>>>> >>>  #include <odp.h>
>>>>>>> >>>  #include "odp_cunit_common.h"
>>>>>>> >>> +#include "test_debug.h"
>>>>>>> >>>
>>>>>>> >>>  /** @private Timeout range in milliseconds (ms) */
>>>>>>> >>>  #define RANGE_MS 2000
>>>>>>> >>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>>>>> >>>  /** @private Timer pool handle used by all threads */
>>>>>>> >>>  static odp_timer_pool_t tp;
>>>>>>> >>>
>>>>>>> >>> +/** @private Count of timeouts delivered too late */
>>>>>>> >>> +static odp_atomic_u32_t ndelivtoolate;
>>>>>>> >>> +
>>>>>>> >>>  /** @private min() function */
>>>>>>> >>>  static int min(int a, int b)
>>>>>>> >>>  {
>>>>>>> >>> @@ -47,8 +53,7 @@ struct test_timer {
>>>>>>> >>>  /* @private Handle a received (timeout) buffer */
>>>>>>> >>>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>>>>>> prev_tick)
>>>>>>> >>>  {
>>>>>>> >>> -       /* Use assert() for internal correctness checks of test
>>>>>>> program */
>>>>>>> >>> -       assert(buf != ODP_BUFFER_INVALID);
>>>>>>> >>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>>>>>> error */
>>>>>>> >>>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>>>>> >>>                 /* Not a timeout buffer */
>>>>>>> >>>                 CU_FAIL("Unexpected buffer type received");
>>>>>>> >>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf,
>>>>>>> bool stale,
>>>>>>> >>> uint64_t prev_tick)
>>>>>>> >>>         if (ttp == NULL)
>>>>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>>>>> >>>
>>>>>>> >>> -       if (ttp->buf2 != buf)
>>>>>>> >>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>>>>> >>>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>>>>>> >>> -       if (ttp->tim != tim)
>>>>>>> >>> +       if (ttp != NULL && ttp->tim != tim)
>>>>>>> >>>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>>>>>> >>>         if (stale) {
>>>>>>> >>>                 if (odp_timeout_fresh(tmo))
>>>>>>> >>>                         CU_FAIL("Wrong status (fresh) for stale
>>>>>>> timeout");
>>>>>>> >>>                 /* Stale timeout => local timer must have
>>>>>>> invalid tick */
>>>>>>> >>> -               if (ttp->tick != TICK_INVALID)
>>>>>>> >>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>>>>> >>>                         CU_FAIL("Stale timeout for active
>>>>>>> timer");
>>>>>>> >>>         } else {
>>>>>>> >>>                 if (!odp_timeout_fresh(tmo))
>>>>>>> >>>                         CU_FAIL("Wrong status (stale) for fresh
>>>>>>> timeout");
>>>>>>> >>>                 /* Fresh timeout => local timer must have
>>>>>>> matching tick */
>>>>>>> >>> -               if (ttp->tick != tick) {
>>>>>>> >>> -                       printf("Wrong tick: expected %"PRIu64"
>>>>>>> actual
>>>>>>> >>> %"PRIu64"\n",
>>>>>>> >>> -                              ttp->tick, tick);
>>>>>>> >>> +               if (ttp != NULL && ttp->tick != tick) {
>>>>>>> >>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>>>>>> actual
>>>>>>> >>> %"PRIu64"\n",
>>>>>>> >>> +                               ttp->tick, tick);
>>>>>>> >>>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>>>>>> >>>                 }
>>>>>>> >>>                 /* Check that timeout was delivered 'timely' */
>>>>>>> >>>                 if (tick > odp_timer_current_tick(tp))
>>>>>>> >>>                         CU_FAIL("Timeout delivered early");
>>>>>>> >>>                 if (tick < prev_tick) {
>>>>>>> >>> -                       printf("Too late tick: %"PRIu64"
>>>>>>> prev_tick
>>>>>>> >>> %"PRIu64"\n",
>>>>>>> >>> -                              tick, prev_tick);
>>>>>>> >>> -                       CU_FAIL("Timeout delivered late");
>>>>>>> >>> +                       LOG_DBG("Too late tick: %"PRIu64"
>>>>>>> prev_tick
>>>>>>> >>> %"PRIu64"\n",
>>>>>>> >>> +                               tick, prev_tick);
>>>>>>> >>> +                       /* We don't report late timeouts using
>>>>>>> CU_FAIL */
>>>>>>> >>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>>>>> >>>                 }
>>>>>>> >>>         }
>>>>>>> >>>
>>>>>>> >>> -       /* Use assert() for correctness check of test program
>>>>>>> itself */
>>>>>>> >>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>> >>> -       ttp->buf = buf;
>>>>>>> >>> +       if (ttp != NULL) {
>>>>>>> >>> +               /* Internal error */
>>>>>>> >>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>> >>> +               ttp->buf = buf;
>>>>>>> >>> +       }
>>>>>>> >>>  }
>>>>>>> >>>
>>>>>>> >>>  /* @private Worker thread entrypoint which performs timer
>>>>>>> >>> alloc/set/cancel/free
>>>>>>> >>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>>>>> >>>                         /* Save expected expiration tick */
>>>>>>> >>>                         tt[i].tick = cur_tick + tck;
>>>>>>> >>>                 }
>>>>>>> >>> -               if (usleep(1000/*1ms*/) < 0)
>>>>>>> >>> -                       perror("usleep"), abort();
>>>>>>> >>> +               struct timespec ts;
>>>>>>> >>> +               ts.tv_sec = 0;
>>>>>>> >>> +               ts.tv_nsec = 1000000; /* 1ms */
>>>>>>> >>> +               if (nanosleep(&ts, NULL) < 0)
>>>>>>> >>> +                       perror("nanosleep"), abort();
>>>>>>> >>>         }
>>>>>>> >>>
>>>>>>> >>>         /* Cancel and free all timers */
>>>>>>> >>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>>>>> >>>                         CU_FAIL("odp_timer_free");
>>>>>>> >>>         }
>>>>>>> >>>
>>>>>>> >>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>>>>>> >>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>> >>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>>>> >>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>>>>>> >>> -              thr, ntoolate);
>>>>>>> >>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>> >>> -       printf("Thread %u: %u stale timeout(s) after
>>>>>>> odp_timer_free()\n",
>>>>>>> >>> -              thr, nstale);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr,
>>>>>>> ncancel);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too
>>>>>>> late\n",
>>>>>>> >>> +               thr, ntoolate);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>> >>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>>>>>> odp_timer_free()\n",
>>>>>>> >>> +               thr, nstale);
>>>>>>> >>>
>>>>>>> >>>         /* Delay some more to ensure timeouts for expired timers
>>>>>>> can be
>>>>>>> >>>          * received */
>>>>>>> >>> -       usleep(1000/*1ms*/);
>>>>>>> >>> +       struct timespec ts;
>>>>>>> >>> +       ts.tv_sec = 0;
>>>>>>> >>> +       ts.tv_nsec = 1000000; /* 1ms */
>>>>>>> >>> +       if (nanosleep(&ts, NULL) < 0)
>>>>>>> >>> +               perror("nanosleep"), abort();
>>>>>>> >>>         while (nstale != 0) {
>>>>>>> >>>                 odp_buffer_t buf = odp_queue_deq(queue);
>>>>>>> >>>                 if (buf != ODP_BUFFER_INVALID) {
>>>>>>> >>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>>>>> >>>         if (buf != ODP_BUFFER_INVALID)
>>>>>>> >>>                 CU_FAIL("Unexpected buffer received");
>>>>>>> >>>
>>>>>>> >>> -       printf("Thread %u: exiting\n", thr);
>>>>>>> >>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>>>>> >>>         return NULL;
>>>>>>> >>>  }
>>>>>>> >>>
>>>>>>> >>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>>>>> >>>  {
>>>>>>> >>>         odp_buffer_pool_param_t params;
>>>>>>> >>>         odp_timer_pool_param_t tparam;
>>>>>>> >>> -       /* This is a stressfull test - need to reserve some cpu
>>>>>>> cycles
>>>>>>> >>> -        * @TODO move to test/performance */
>>>>>>> >>> -       int num_workers = min(odp_sys_cpu_count()-1,
>>>>>>> MAX_WORKERS);
>>>>>>> >>> +       /* Reserve at least one core for running other processes
>>>>>>> so the
>>>>>>> >>> timer
>>>>>>> >>> +        * test hopefully can run undisturbed and thus get
>>>>>>> better timing
>>>>>>> >>> +        * results. */
>>>>>>> >>> +       int num_workers = min(odp_sys_cpu_count() - 1,
>>>>>>> MAX_WORKERS);
>>>>>>> >>> +       /* On a single-CPU machine run at least one thread */
>>>>>>> >>> +       if (num_workers < 1)
>>>>>>> >>> +               num_workers = 1;
>>>>>>> >>>
>>>>>>> >>>         /* Create timeout buffer pools */
>>>>>>> >>>         params.buf_size  = 0;
>>>>>>> >>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>>>>> >>>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>>>>>> >>>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>>>>> >>>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>>>>>> >>> -       printf("Timer pool\n");
>>>>>>> >>> -       printf("----------\n");
>>>>>>> >>> -       printf("  name: %s\n", tpinfo.name);
>>>>>>> >>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>>>>>> >>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>>>>>> >>> -       printf("  min tmo: %"PRIu64" ns\n",
>>>>>>> tpinfo.param.min_tmo);
>>>>>>> >>> -       printf("  max tmo: %"PRIu64" ns\n",
>>>>>>> tpinfo.param.max_tmo);
>>>>>>> >>> -       printf("\n");
>>>>>>> >>> -
>>>>>>> >>> -       printf("#timers..: %u\n", NTIMERS);
>>>>>>> >>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>> >>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>> >>> -       printf("\n");
>>>>>>> >>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>>>>>> >>> +
>>>>>>> >>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>>>>>> >>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>> >>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>> >>>
>>>>>>> >>>         uint64_t tick;
>>>>>>> >>>         for (tick = 0; tick < 1000000000000ULL; tick +=
>>>>>>> 1000000ULL) {
>>>>>>> >>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>>>>> >>>         /* Initialize barrier used by worker threads for
>>>>>>> synchronization
>>>>>>> >>> */
>>>>>>> >>>         odp_barrier_init(&test_barrier, num_workers);
>>>>>>> >>>
>>>>>>> >>> +       /* Initialize the shared timeout counter */
>>>>>>> >>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>>>>>> >>> +
>>>>>>> >>>         /* Create and start worker threads */
>>>>>>> >>>         pthrd_arg thrdarg;
>>>>>>> >>>         thrdarg.testcase = 0;
>>>>>>> >>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>>>>> >>>
>>>>>>> >>>         /* Wait for worker threads to exit */
>>>>>>> >>>         odp_cunit_thread_exit(&thrdarg);
>>>>>>> >>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>>>>>> %u\n",
>>>>>>> >>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>>>>> >>>
>>>>>>> >>>         /* Check some statistics after the test */
>>>>>>> >>>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>>>>>> >>> --
>>>>>>> >>> 1.9.1
>>>>>>> >>>
>>>>>>> >>>
>>>>>>> >>> _______________________________________________
>>>>>>> >>> lng-odp mailing list
>>>>>>> >>> lng-odp@lists.linaro.org
>>>>>>> >>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>> >>
>>>>>>> >>
>>>>>>> >>
>>>>>>> >>
>>>>>>> >> --
>>>>>>> >> Mike Holmes
>>>>>>> >> Linaro  Sr Technical Manager
>>>>>>> >> LNG - ODP
>>>>>>> >>
>>>>>>> >> _______________________________________________
>>>>>>> >> lng-odp mailing list
>>>>>>> >> lng-odp@lists.linaro.org
>>>>>>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>> >>
>>>>>>>
>>>>>>> _______________________________________________
>>>>>>> lng-odp mailing list
>>>>>>> lng-odp@lists.linaro.org
>>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>>
>>>>>>
>>>>>> _______________________________________________
>>>>>> lng-odp mailing list
>>>>>> lng-odp@lists.linaro.org
>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>
>>>>>
>>>>
>>>> _______________________________________________
>>>> lng-odp mailing list
>>>> lng-odp@lists.linaro.org
>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>
>>>>
>>>
>>>
>>> --
>>> *Mike Holmes*
>>> Linaro  Sr Technical Manager
>>> LNG - ODP
>>>
>>
>>
Mike Holmes Jan. 16, 2015, 1:49 p.m. | #9
On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org> wrote:

> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
> >
> >
> > On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
> wrote:
> >>
> >> Don't report too late timeouts using CU_FAIL as this interferes with the
> >> cunit
> >> test framework. Just count and report (using LOG_DBG) the number of late
> >> timeouts.
> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
> >> cunit
> >> test framework.
> >> Don't dereference pointer after successful check for NULL as this makes
> >> Coverity
> >> complain.
> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> >> Use nanosleep instead of the deprecated usleep.
> >>
> >> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
> >
> >
> > Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>
> May I suggest splitting this as a patch set?
> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
>
> Cheers,
> Anders
>
>
I think that although what is considered the correct level of division for
a patch is debatable,  following  the rule - "fix one thing per patch" bug
fixes should always be their own patch and that is an easily identified and
enforced division.
Even if issues did not make it to bugzilla and have a bug ID, the patch
description often tells the story as in this case

One bug - regression framework
Don't report too late timeouts using CU_FAIL as this interferes with the
cunit
test framework. Just count and report (using LOG_DBG) the number of late
timeouts.  If it had one the BZ ID should be here

Two bug - static analysis
Don't dereference pointer after successful check for NULL as this makes
Coverity
complain. - should reference the COV: ID for this issue

Three - clean up to test as per review comments
Use CU_ASSERT_FATAL instead of plain assert so to work wither with the cunit
test framework.
Use LOG_DBG instead of printf. Remove some unnecessary printouts.
Use nanosleep instead of the deprecated usleep.



>
> >>
> >> ---
> >> (This document/code contribution attached is provided under the terms of
> >> agreement LES-LTM-21309)
> >>
> >>  test/validation/odp_timer.c | 102
> >> +++++++++++++++++++++++++-------------------
> >>  1 file changed, 59 insertions(+), 43 deletions(-)
> >>
> >> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
> >> index 4c93f71..d893646 100644
> >> --- a/test/validation/odp_timer.c
> >> +++ b/test/validation/odp_timer.c
> >> @@ -8,10 +8,13 @@
> >>   * @file
> >>   */
> >>
> >> -#include <assert.h>
> >> +/* For rand_r and nanosleep */
> >> +#define _POSIX_C_SOURCE 200112L
> >> +#include <time.h>
> >>  #include <unistd.h>
> >>  #include <odp.h>
> >>  #include "odp_cunit_common.h"
> >> +#include "test_debug.h"
> >>
> >>  /** @private Timeout range in milliseconds (ms) */
> >>  #define RANGE_MS 2000
> >> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
> >>  /** @private Timer pool handle used by all threads */
> >>  static odp_timer_pool_t tp;
> >>
> >> +/** @private Count of timeouts delivered too late */
> >> +static odp_atomic_u32_t ndelivtoolate;
> >> +
> >>  /** @private min() function */
> >>  static int min(int a, int b)
> >>  {
> >> @@ -47,8 +53,7 @@ struct test_timer {
> >>  /* @private Handle a received (timeout) buffer */
> >>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
> prev_tick)
> >>  {
> >> -       /* Use assert() for internal correctness checks of test program
> */
> >> -       assert(buf != ODP_BUFFER_INVALID);
> >> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error */
> >>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
> >>                 /* Not a timeout buffer */
> >>                 CU_FAIL("Unexpected buffer type received");
> >> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool stale,
> >> uint64_t prev_tick)
> >>         if (ttp == NULL)
> >>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
> >>
> >> -       if (ttp->buf2 != buf)
> >> +       if (ttp != NULL && ttp->buf2 != buf)
> >>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
> >> -       if (ttp->tim != tim)
> >> +       if (ttp != NULL && ttp->tim != tim)
> >>                 CU_FAIL("odp_timeout_timer() wrong timer");
> >>         if (stale) {
> >>                 if (odp_timeout_fresh(tmo))
> >>                         CU_FAIL("Wrong status (fresh) for stale
> timeout");
> >>                 /* Stale timeout => local timer must have invalid tick
> */
> >> -               if (ttp->tick != TICK_INVALID)
> >> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
> >>                         CU_FAIL("Stale timeout for active timer");
> >>         } else {
> >>                 if (!odp_timeout_fresh(tmo))
> >>                         CU_FAIL("Wrong status (stale) for fresh
> timeout");
> >>                 /* Fresh timeout => local timer must have matching tick
> */
> >> -               if (ttp->tick != tick) {
> >> -                       printf("Wrong tick: expected %"PRIu64" actual
> >> %"PRIu64"\n",
> >> -                              ttp->tick, tick);
> >> +               if (ttp != NULL && ttp->tick != tick) {
> >> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
> >> %"PRIu64"\n",
> >> +                               ttp->tick, tick);
> >>                         CU_FAIL("odp_timeout_tick() wrong tick");
> >>                 }
> >>                 /* Check that timeout was delivered 'timely' */
> >>                 if (tick > odp_timer_current_tick(tp))
> >>                         CU_FAIL("Timeout delivered early");
> >>                 if (tick < prev_tick) {
> >> -                       printf("Too late tick: %"PRIu64" prev_tick
> >> %"PRIu64"\n",
> >> -                              tick, prev_tick);
> >> -                       CU_FAIL("Timeout delivered late");
> >> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
> >> %"PRIu64"\n",
> >> +                               tick, prev_tick);
> >> +                       /* We don't report late timeouts using CU_FAIL
> */
> >> +                       odp_atomic_inc_u32(&ndelivtoolate);
> >>                 }
> >>         }
> >>
> >> -       /* Use assert() for correctness check of test program itself */
> >> -       assert(ttp->buf == ODP_BUFFER_INVALID);
> >> -       ttp->buf = buf;
> >> +       if (ttp != NULL) {
> >> +               /* Internal error */
> >> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
> >> +               ttp->buf = buf;
> >> +       }
> >>  }
> >>
> >>  /* @private Worker thread entrypoint which performs timer
> >> alloc/set/cancel/free
> >> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
> >>                         /* Save expected expiration tick */
> >>                         tt[i].tick = cur_tick + tck;
> >>                 }
> >> -               if (usleep(1000/*1ms*/) < 0)
> >> -                       perror("usleep"), abort();
> >> +               struct timespec ts;
> >> +               ts.tv_sec = 0;
> >> +               ts.tv_nsec = 1000000; /* 1ms */
> >> +               if (nanosleep(&ts, NULL) < 0)
> >> +                       perror("nanosleep"), abort();
> >>         }
> >>
> >>         /* Cancel and free all timers */
> >> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
> >>                         CU_FAIL("odp_timer_free");
> >>         }
> >>
> >> -       printf("Thread %u: %u timers set\n", thr, nset);
> >> -       printf("Thread %u: %u timers reset\n", thr, nreset);
> >> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
> >> -       printf("Thread %u: %u timers reset/cancelled too late\n",
> >> -              thr, ntoolate);
> >> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
> >> -       printf("Thread %u: %u stale timeout(s) after
> odp_timer_free()\n",
> >> -              thr, nstale);
> >> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
> >> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
> >> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
> >> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
> >> +               thr, ntoolate);
> >> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
> >> +       LOG_DBG("Thread %u: %u stale timeout(s) after
> odp_timer_free()\n",
> >> +               thr, nstale);
> >>
> >>         /* Delay some more to ensure timeouts for expired timers can be
> >>          * received */
> >> -       usleep(1000/*1ms*/);
> >> +       struct timespec ts;
> >> +       ts.tv_sec = 0;
> >> +       ts.tv_nsec = 1000000; /* 1ms */
> >> +       if (nanosleep(&ts, NULL) < 0)
> >> +               perror("nanosleep"), abort();
> >>         while (nstale != 0) {
> >>                 odp_buffer_t buf = odp_queue_deq(queue);
> >>                 if (buf != ODP_BUFFER_INVALID) {
> >> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
> >>         if (buf != ODP_BUFFER_INVALID)
> >>                 CU_FAIL("Unexpected buffer received");
> >>
> >> -       printf("Thread %u: exiting\n", thr);
> >> +       LOG_DBG("Thread %u: exiting\n", thr);
> >>         return NULL;
> >>  }
> >>
> >> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
> >>  {
> >>         odp_buffer_pool_param_t params;
> >>         odp_timer_pool_param_t tparam;
> >> -       /* This is a stressfull test - need to reserve some cpu cycles
> >> -        * @TODO move to test/performance */
> >> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
> >> +       /* Reserve at least one core for running other processes so the
> >> timer
> >> +        * test hopefully can run undisturbed and thus get better timing
> >> +        * results. */
> >> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
> >> +       /* On a single-CPU machine run at least one thread */
> >> +       if (num_workers < 1)
> >> +               num_workers = 1;
> >>
> >>         /* Create timeout buffer pools */
> >>         params.buf_size  = 0;
> >> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
> >>         CU_ASSERT(tpinfo.param.res_ns == RES);
> >>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
> >>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
> >> -       printf("Timer pool\n");
> >> -       printf("----------\n");
> >> -       printf("  name: %s\n", tpinfo.name);
> >> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
> >> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
> >> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
> >> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
> >> -       printf("\n");
> >> -
> >> -       printf("#timers..: %u\n", NTIMERS);
> >> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >> -       printf("\n");
> >> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
> >> +
> >> +       LOG_DBG("#timers..: %u\n", NTIMERS);
> >> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >>
> >>         uint64_t tick;
> >>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
> >> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
> >>         /* Initialize barrier used by worker threads for synchronization
> >> */
> >>         odp_barrier_init(&test_barrier, num_workers);
> >>
> >> +       /* Initialize the shared timeout counter */
> >> +       odp_atomic_init_u32(&ndelivtoolate, 0);
> >> +
> >>         /* Create and start worker threads */
> >>         pthrd_arg thrdarg;
> >>         thrdarg.testcase = 0;
> >> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
> >>
> >>         /* Wait for worker threads to exit */
> >>         odp_cunit_thread_exit(&thrdarg);
> >> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
> >> +               odp_atomic_load_u32(&ndelivtoolate));
> >>
> >>         /* Check some statistics after the test */
> >>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
> >> --
> >> 1.9.1
> >>
> >>
> >> _______________________________________________
> >> lng-odp mailing list
> >> lng-odp@lists.linaro.org
> >> http://lists.linaro.org/mailman/listinfo/lng-odp
> >
> >
> >
> >
> > --
> > Mike Holmes
> > Linaro  Sr Technical Manager
> > LNG - ODP
> >
> > _______________________________________________
> > lng-odp mailing list
> > lng-odp@lists.linaro.org
> > http://lists.linaro.org/mailman/listinfo/lng-odp
> >
>
Mike Holmes Jan. 20, 2015, 5:45 p.m. | #10
This is a blocker since it breaks CI, we need an update the test to not
fail on discovering that timeouts were late or disable the timer tests with
XFAIL

On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org> wrote:

>
>
> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
> wrote:
>
>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
>> >
>> >
>> > On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
>> wrote:
>> >>
>> >> Don't report too late timeouts using CU_FAIL as this interferes with
>> the
>> >> cunit
>> >> test framework. Just count and report (using LOG_DBG) the number of
>> late
>> >> timeouts.
>> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>> >> cunit
>> >> test framework.
>> >> Don't dereference pointer after successful check for NULL as this makes
>> >> Coverity
>> >> complain.
>> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>> >> Use nanosleep instead of the deprecated usleep.
>> >>
>> >> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>> >
>> >
>> > Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>
>> May I suggest splitting this as a patch set?
>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
>>
>> Cheers,
>> Anders
>>
>>
> I think that although what is considered the correct level of division for
> a patch is debatable,  following  the rule - "fix one thing per patch" bug
> fixes should always be their own patch and that is an easily identified and
> enforced division.
> Even if issues did not make it to bugzilla and have a bug ID, the patch
> description often tells the story as in this case
>
> One bug - regression framework
> Don't report too late timeouts using CU_FAIL as this interferes with the
> cunit
> test framework. Just count and report (using LOG_DBG) the number of late
> timeouts.  If it had one the BZ ID should be here
>
> Two bug - static analysis
> Don't dereference pointer after successful check for NULL as this makes
> Coverity
> complain. - should reference the COV: ID for this issue
>
> Three - clean up to test as per review comments
> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
> cunit
> test framework.
> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> Use nanosleep instead of the deprecated usleep.
>
>
>
> >
>> >>
>>
>> >> ---
>> >> (This document/code contribution attached is provided under the terms
>> of
>> >> agreement LES-LTM-21309)
>> >>
>> >>  test/validation/odp_timer.c | 102
>> >> +++++++++++++++++++++++++-------------------
>> >>  1 file changed, 59 insertions(+), 43 deletions(-)
>> >>
>> >> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
>> >> index 4c93f71..d893646 100644
>> >> --- a/test/validation/odp_timer.c
>> >> +++ b/test/validation/odp_timer.c
>> >> @@ -8,10 +8,13 @@
>> >>   * @file
>> >>   */
>> >>
>> >> -#include <assert.h>
>> >> +/* For rand_r and nanosleep */
>> >> +#define _POSIX_C_SOURCE 200112L
>> >> +#include <time.h>
>> >>  #include <unistd.h>
>> >>  #include <odp.h>
>> >>  #include "odp_cunit_common.h"
>> >> +#include "test_debug.h"
>> >>
>> >>  /** @private Timeout range in milliseconds (ms) */
>> >>  #define RANGE_MS 2000
>> >> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>> >>  /** @private Timer pool handle used by all threads */
>> >>  static odp_timer_pool_t tp;
>> >>
>> >> +/** @private Count of timeouts delivered too late */
>> >> +static odp_atomic_u32_t ndelivtoolate;
>> >> +
>> >>  /** @private min() function */
>> >>  static int min(int a, int b)
>> >>  {
>> >> @@ -47,8 +53,7 @@ struct test_timer {
>> >>  /* @private Handle a received (timeout) buffer */
>> >>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>> prev_tick)
>> >>  {
>> >> -       /* Use assert() for internal correctness checks of test
>> program */
>> >> -       assert(buf != ODP_BUFFER_INVALID);
>> >> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error
>> */
>> >>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>> >>                 /* Not a timeout buffer */
>> >>                 CU_FAIL("Unexpected buffer type received");
>> >> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>> stale,
>> >> uint64_t prev_tick)
>> >>         if (ttp == NULL)
>> >>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>> >>
>> >> -       if (ttp->buf2 != buf)
>> >> +       if (ttp != NULL && ttp->buf2 != buf)
>> >>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>> >> -       if (ttp->tim != tim)
>> >> +       if (ttp != NULL && ttp->tim != tim)
>> >>                 CU_FAIL("odp_timeout_timer() wrong timer");
>> >>         if (stale) {
>> >>                 if (odp_timeout_fresh(tmo))
>> >>                         CU_FAIL("Wrong status (fresh) for stale
>> timeout");
>> >>                 /* Stale timeout => local timer must have invalid tick
>> */
>> >> -               if (ttp->tick != TICK_INVALID)
>> >> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>> >>                         CU_FAIL("Stale timeout for active timer");
>> >>         } else {
>> >>                 if (!odp_timeout_fresh(tmo))
>> >>                         CU_FAIL("Wrong status (stale) for fresh
>> timeout");
>> >>                 /* Fresh timeout => local timer must have matching
>> tick */
>> >> -               if (ttp->tick != tick) {
>> >> -                       printf("Wrong tick: expected %"PRIu64" actual
>> >> %"PRIu64"\n",
>> >> -                              ttp->tick, tick);
>> >> +               if (ttp != NULL && ttp->tick != tick) {
>> >> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
>> >> %"PRIu64"\n",
>> >> +                               ttp->tick, tick);
>> >>                         CU_FAIL("odp_timeout_tick() wrong tick");
>> >>                 }
>> >>                 /* Check that timeout was delivered 'timely' */
>> >>                 if (tick > odp_timer_current_tick(tp))
>> >>                         CU_FAIL("Timeout delivered early");
>> >>                 if (tick < prev_tick) {
>> >> -                       printf("Too late tick: %"PRIu64" prev_tick
>> >> %"PRIu64"\n",
>> >> -                              tick, prev_tick);
>> >> -                       CU_FAIL("Timeout delivered late");
>> >> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>> >> %"PRIu64"\n",
>> >> +                               tick, prev_tick);
>> >> +                       /* We don't report late timeouts using CU_FAIL
>> */
>> >> +                       odp_atomic_inc_u32(&ndelivtoolate);
>> >>                 }
>> >>         }
>> >>
>> >> -       /* Use assert() for correctness check of test program itself */
>> >> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>> >> -       ttp->buf = buf;
>> >> +       if (ttp != NULL) {
>> >> +               /* Internal error */
>> >> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>> >> +               ttp->buf = buf;
>> >> +       }
>> >>  }
>> >>
>> >>  /* @private Worker thread entrypoint which performs timer
>> >> alloc/set/cancel/free
>> >> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>> >>                         /* Save expected expiration tick */
>> >>                         tt[i].tick = cur_tick + tck;
>> >>                 }
>> >> -               if (usleep(1000/*1ms*/) < 0)
>> >> -                       perror("usleep"), abort();
>> >> +               struct timespec ts;
>> >> +               ts.tv_sec = 0;
>> >> +               ts.tv_nsec = 1000000; /* 1ms */
>> >> +               if (nanosleep(&ts, NULL) < 0)
>> >> +                       perror("nanosleep"), abort();
>> >>         }
>> >>
>> >>         /* Cancel and free all timers */
>> >> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>> >>                         CU_FAIL("odp_timer_free");
>> >>         }
>> >>
>> >> -       printf("Thread %u: %u timers set\n", thr, nset);
>> >> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>> >> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>> >> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>> >> -              thr, ntoolate);
>> >> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>> >> -       printf("Thread %u: %u stale timeout(s) after
>> odp_timer_free()\n",
>> >> -              thr, nstale);
>> >> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>> >> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>> >> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>> >> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>> >> +               thr, ntoolate);
>> >> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>> >> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>> odp_timer_free()\n",
>> >> +               thr, nstale);
>> >>
>> >>         /* Delay some more to ensure timeouts for expired timers can be
>> >>          * received */
>> >> -       usleep(1000/*1ms*/);
>> >> +       struct timespec ts;
>> >> +       ts.tv_sec = 0;
>> >> +       ts.tv_nsec = 1000000; /* 1ms */
>> >> +       if (nanosleep(&ts, NULL) < 0)
>> >> +               perror("nanosleep"), abort();
>> >>         while (nstale != 0) {
>> >>                 odp_buffer_t buf = odp_queue_deq(queue);
>> >>                 if (buf != ODP_BUFFER_INVALID) {
>> >> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>> >>         if (buf != ODP_BUFFER_INVALID)
>> >>                 CU_FAIL("Unexpected buffer received");
>> >>
>> >> -       printf("Thread %u: exiting\n", thr);
>> >> +       LOG_DBG("Thread %u: exiting\n", thr);
>> >>         return NULL;
>> >>  }
>> >>
>> >> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>> >>  {
>> >>         odp_buffer_pool_param_t params;
>> >>         odp_timer_pool_param_t tparam;
>> >> -       /* This is a stressfull test - need to reserve some cpu cycles
>> >> -        * @TODO move to test/performance */
>> >> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>> >> +       /* Reserve at least one core for running other processes so the
>> >> timer
>> >> +        * test hopefully can run undisturbed and thus get better
>> timing
>> >> +        * results. */
>> >> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>> >> +       /* On a single-CPU machine run at least one thread */
>> >> +       if (num_workers < 1)
>> >> +               num_workers = 1;
>> >>
>> >>         /* Create timeout buffer pools */
>> >>         params.buf_size  = 0;
>> >> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>> >>         CU_ASSERT(tpinfo.param.res_ns == RES);
>> >>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>> >>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>> >> -       printf("Timer pool\n");
>> >> -       printf("----------\n");
>> >> -       printf("  name: %s\n", tpinfo.name);
>> >> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>> >> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>> >> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>> >> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>> >> -       printf("\n");
>> >> -
>> >> -       printf("#timers..: %u\n", NTIMERS);
>> >> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> >> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>> >> -       printf("\n");
>> >> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>> >> +
>> >> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>> >> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> >> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>> >>
>> >>         uint64_t tick;
>> >>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
>> >> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>> >>         /* Initialize barrier used by worker threads for
>> synchronization
>> >> */
>> >>         odp_barrier_init(&test_barrier, num_workers);
>> >>
>> >> +       /* Initialize the shared timeout counter */
>> >> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>> >> +
>> >>         /* Create and start worker threads */
>> >>         pthrd_arg thrdarg;
>> >>         thrdarg.testcase = 0;
>> >> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>> >>
>> >>         /* Wait for worker threads to exit */
>> >>         odp_cunit_thread_exit(&thrdarg);
>> >> +       LOG_DBG("Number of timeouts delivered/received too late: %u\n",
>> >> +               odp_atomic_load_u32(&ndelivtoolate));
>> >>
>> >>         /* Check some statistics after the test */
>> >>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>> >> --
>> >> 1.9.1
>> >>
>> >>
>> >> _______________________________________________
>> >> lng-odp mailing list
>> >> lng-odp@lists.linaro.org
>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>> >
>> >
>> >
>> >
>> > --
>> > Mike Holmes
>> > Linaro  Sr Technical Manager
>> > LNG - ODP
>> >
>> > _______________________________________________
>> > lng-odp mailing list
>> > lng-odp@lists.linaro.org
>> > http://lists.linaro.org/mailman/listinfo/lng-odp
>> >
>>
>
>
>
> --
> *Mike Holmes*
> Linaro  Sr Technical Manager
> LNG - ODP
>
Ola Liljedahl Jan. 21, 2015, 12:43 p.m. | #11
You have the patches, what are you waiting for?

On 20 January 2015 at 17:45, Mike Holmes <mike.holmes@linaro.org> wrote:
> This is a blocker since it breaks CI, we need an update the test to not fail
> on discovering that timeouts were late or disable the timer tests with XFAIL
>
> On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org> wrote:
>>
>>
>>
>> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
>> wrote:
>>>
>>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org> wrote:
>>> >
>>> >
>>> > On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org>
>>> > wrote:
>>> >>
>>> >> Don't report too late timeouts using CU_FAIL as this interferes with
>>> >> the
>>> >> cunit
>>> >> test framework. Just count and report (using LOG_DBG) the number of
>>> >> late
>>> >> timeouts.
>>> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>>> >> cunit
>>> >> test framework.
>>> >> Don't dereference pointer after successful check for NULL as this
>>> >> makes
>>> >> Coverity
>>> >> complain.
>>> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>> >> Use nanosleep instead of the deprecated usleep.
>>> >>
>>> >> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>> >
>>> >
>>> > Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>
>>> May I suggest splitting this as a patch set?
>>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
>>>
>>> Cheers,
>>> Anders
>>>
>>
>> I think that although what is considered the correct level of division for
>> a patch is debatable,  following  the rule - "fix one thing per patch" bug
>> fixes should always be their own patch and that is an easily identified and
>> enforced division.
>> Even if issues did not make it to bugzilla and have a bug ID, the patch
>> description often tells the story as in this case
>>
>> One bug - regression framework
>> Don't report too late timeouts using CU_FAIL as this interferes with the
>> cunit
>> test framework. Just count and report (using LOG_DBG) the number of late
>> timeouts.  If it had one the BZ ID should be here
>>
>> Two bug - static analysis
>> Don't dereference pointer after successful check for NULL as this makes
>> Coverity
>> complain. - should reference the COV: ID for this issue
>>
>> Three - clean up to test as per review comments
>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>> cunit
>> test framework.
>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>> Use nanosleep instead of the deprecated usleep.
>>
>>
>>
>>> >
>>> >>
>>>
>>> >> ---
>>> >> (This document/code contribution attached is provided under the terms
>>> >> of
>>> >> agreement LES-LTM-21309)
>>> >>
>>> >>  test/validation/odp_timer.c | 102
>>> >> +++++++++++++++++++++++++-------------------
>>> >>  1 file changed, 59 insertions(+), 43 deletions(-)
>>> >>
>>> >> diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
>>> >> index 4c93f71..d893646 100644
>>> >> --- a/test/validation/odp_timer.c
>>> >> +++ b/test/validation/odp_timer.c
>>> >> @@ -8,10 +8,13 @@
>>> >>   * @file
>>> >>   */
>>> >>
>>> >> -#include <assert.h>
>>> >> +/* For rand_r and nanosleep */
>>> >> +#define _POSIX_C_SOURCE 200112L
>>> >> +#include <time.h>
>>> >>  #include <unistd.h>
>>> >>  #include <odp.h>
>>> >>  #include "odp_cunit_common.h"
>>> >> +#include "test_debug.h"
>>> >>
>>> >>  /** @private Timeout range in milliseconds (ms) */
>>> >>  #define RANGE_MS 2000
>>> >> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>> >>  /** @private Timer pool handle used by all threads */
>>> >>  static odp_timer_pool_t tp;
>>> >>
>>> >> +/** @private Count of timeouts delivered too late */
>>> >> +static odp_atomic_u32_t ndelivtoolate;
>>> >> +
>>> >>  /** @private min() function */
>>> >>  static int min(int a, int b)
>>> >>  {
>>> >> @@ -47,8 +53,7 @@ struct test_timer {
>>> >>  /* @private Handle a received (timeout) buffer */
>>> >>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>> >> prev_tick)
>>> >>  {
>>> >> -       /* Use assert() for internal correctness checks of test
>>> >> program */
>>> >> -       assert(buf != ODP_BUFFER_INVALID);
>>> >> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error
>>> >> */
>>> >>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>> >>                 /* Not a timeout buffer */
>>> >>                 CU_FAIL("Unexpected buffer type received");
>>> >> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>> >> stale,
>>> >> uint64_t prev_tick)
>>> >>         if (ttp == NULL)
>>> >>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>> >>
>>> >> -       if (ttp->buf2 != buf)
>>> >> +       if (ttp != NULL && ttp->buf2 != buf)
>>> >>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>> >> -       if (ttp->tim != tim)
>>> >> +       if (ttp != NULL && ttp->tim != tim)
>>> >>                 CU_FAIL("odp_timeout_timer() wrong timer");
>>> >>         if (stale) {
>>> >>                 if (odp_timeout_fresh(tmo))
>>> >>                         CU_FAIL("Wrong status (fresh) for stale
>>> >> timeout");
>>> >>                 /* Stale timeout => local timer must have invalid tick
>>> >> */
>>> >> -               if (ttp->tick != TICK_INVALID)
>>> >> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>> >>                         CU_FAIL("Stale timeout for active timer");
>>> >>         } else {
>>> >>                 if (!odp_timeout_fresh(tmo))
>>> >>                         CU_FAIL("Wrong status (stale) for fresh
>>> >> timeout");
>>> >>                 /* Fresh timeout => local timer must have matching
>>> >> tick */
>>> >> -               if (ttp->tick != tick) {
>>> >> -                       printf("Wrong tick: expected %"PRIu64" actual
>>> >> %"PRIu64"\n",
>>> >> -                              ttp->tick, tick);
>>> >> +               if (ttp != NULL && ttp->tick != tick) {
>>> >> +                       LOG_DBG("Wrong tick: expected %"PRIu64" actual
>>> >> %"PRIu64"\n",
>>> >> +                               ttp->tick, tick);
>>> >>                         CU_FAIL("odp_timeout_tick() wrong tick");
>>> >>                 }
>>> >>                 /* Check that timeout was delivered 'timely' */
>>> >>                 if (tick > odp_timer_current_tick(tp))
>>> >>                         CU_FAIL("Timeout delivered early");
>>> >>                 if (tick < prev_tick) {
>>> >> -                       printf("Too late tick: %"PRIu64" prev_tick
>>> >> %"PRIu64"\n",
>>> >> -                              tick, prev_tick);
>>> >> -                       CU_FAIL("Timeout delivered late");
>>> >> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>> >> %"PRIu64"\n",
>>> >> +                               tick, prev_tick);
>>> >> +                       /* We don't report late timeouts using CU_FAIL
>>> >> */
>>> >> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>> >>                 }
>>> >>         }
>>> >>
>>> >> -       /* Use assert() for correctness check of test program itself
>>> >> */
>>> >> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>> >> -       ttp->buf = buf;
>>> >> +       if (ttp != NULL) {
>>> >> +               /* Internal error */
>>> >> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>> >> +               ttp->buf = buf;
>>> >> +       }
>>> >>  }
>>> >>
>>> >>  /* @private Worker thread entrypoint which performs timer
>>> >> alloc/set/cancel/free
>>> >> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>> >>                         /* Save expected expiration tick */
>>> >>                         tt[i].tick = cur_tick + tck;
>>> >>                 }
>>> >> -               if (usleep(1000/*1ms*/) < 0)
>>> >> -                       perror("usleep"), abort();
>>> >> +               struct timespec ts;
>>> >> +               ts.tv_sec = 0;
>>> >> +               ts.tv_nsec = 1000000; /* 1ms */
>>> >> +               if (nanosleep(&ts, NULL) < 0)
>>> >> +                       perror("nanosleep"), abort();
>>> >>         }
>>> >>
>>> >>         /* Cancel and free all timers */
>>> >> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>> >>                         CU_FAIL("odp_timer_free");
>>> >>         }
>>> >>
>>> >> -       printf("Thread %u: %u timers set\n", thr, nset);
>>> >> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>> >> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> >> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>> >> -              thr, ntoolate);
>>> >> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>> >> -       printf("Thread %u: %u stale timeout(s) after
>>> >> odp_timer_free()\n",
>>> >> -              thr, nstale);
>>> >> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>> >> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>> >> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>> >> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>> >> +               thr, ntoolate);
>>> >> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>> >> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>> >> odp_timer_free()\n",
>>> >> +               thr, nstale);
>>> >>
>>> >>         /* Delay some more to ensure timeouts for expired timers can
>>> >> be
>>> >>          * received */
>>> >> -       usleep(1000/*1ms*/);
>>> >> +       struct timespec ts;
>>> >> +       ts.tv_sec = 0;
>>> >> +       ts.tv_nsec = 1000000; /* 1ms */
>>> >> +       if (nanosleep(&ts, NULL) < 0)
>>> >> +               perror("nanosleep"), abort();
>>> >>         while (nstale != 0) {
>>> >>                 odp_buffer_t buf = odp_queue_deq(queue);
>>> >>                 if (buf != ODP_BUFFER_INVALID) {
>>> >> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>> >>         if (buf != ODP_BUFFER_INVALID)
>>> >>                 CU_FAIL("Unexpected buffer received");
>>> >>
>>> >> -       printf("Thread %u: exiting\n", thr);
>>> >> +       LOG_DBG("Thread %u: exiting\n", thr);
>>> >>         return NULL;
>>> >>  }
>>> >>
>>> >> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>> >>  {
>>> >>         odp_buffer_pool_param_t params;
>>> >>         odp_timer_pool_param_t tparam;
>>> >> -       /* This is a stressfull test - need to reserve some cpu cycles
>>> >> -        * @TODO move to test/performance */
>>> >> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>> >> +       /* Reserve at least one core for running other processes so
>>> >> the
>>> >> timer
>>> >> +        * test hopefully can run undisturbed and thus get better
>>> >> timing
>>> >> +        * results. */
>>> >> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
>>> >> +       /* On a single-CPU machine run at least one thread */
>>> >> +       if (num_workers < 1)
>>> >> +               num_workers = 1;
>>> >>
>>> >>         /* Create timeout buffer pools */
>>> >>         params.buf_size  = 0;
>>> >> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>> >>         CU_ASSERT(tpinfo.param.res_ns == RES);
>>> >>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>> >>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>> >> -       printf("Timer pool\n");
>>> >> -       printf("----------\n");
>>> >> -       printf("  name: %s\n", tpinfo.name);
>>> >> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>> >> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>> >> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>> >> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>> >> -       printf("\n");
>>> >> -
>>> >> -       printf("#timers..: %u\n", NTIMERS);
>>> >> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> >> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>> >> -       printf("\n");
>>> >> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>> >> +
>>> >> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>> >> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>> >> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>> >>
>>> >>         uint64_t tick;
>>> >>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
>>> >> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>> >>         /* Initialize barrier used by worker threads for
>>> >> synchronization
>>> >> */
>>> >>         odp_barrier_init(&test_barrier, num_workers);
>>> >>
>>> >> +       /* Initialize the shared timeout counter */
>>> >> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>> >> +
>>> >>         /* Create and start worker threads */
>>> >>         pthrd_arg thrdarg;
>>> >>         thrdarg.testcase = 0;
>>> >> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>> >>
>>> >>         /* Wait for worker threads to exit */
>>> >>         odp_cunit_thread_exit(&thrdarg);
>>> >> +       LOG_DBG("Number of timeouts delivered/received too late:
>>> >> %u\n",
>>> >> +               odp_atomic_load_u32(&ndelivtoolate));
>>> >>
>>> >>         /* Check some statistics after the test */
>>> >>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>> >> --
>>> >> 1.9.1
>>> >>
>>> >>
>>> >> _______________________________________________
>>> >> lng-odp mailing list
>>> >> lng-odp@lists.linaro.org
>>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>>> >
>>> >
>>> >
>>> >
>>> > --
>>> > Mike Holmes
>>> > Linaro  Sr Technical Manager
>>> > LNG - ODP
>>> >
>>> > _______________________________________________
>>> > lng-odp mailing list
>>> > lng-odp@lists.linaro.org
>>> > http://lists.linaro.org/mailman/listinfo/lng-odp
>>> >
>>
>>
>>
>>
>> --
>> Mike Holmes
>> Linaro  Sr Technical Manager
>> LNG - ODP
>
>
>
>
> --
> Mike Holmes
> Linaro  Sr Technical Manager
> LNG - ODP
Mike Holmes Jan. 21, 2015, 5:56 p.m. | #12
I don't see a resolution to the request to break up the patch.


On 21 January 2015 at 07:43, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:

> You have the patches, what are you waiting for?
>
> On 20 January 2015 at 17:45, Mike Holmes <mike.holmes@linaro.org> wrote:
> > This is a blocker since it breaks CI, we need an update the test to not
> fail
> > on discovering that timeouts were late or disable the timer tests with
> XFAIL
> >
> > On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org> wrote:
> >>
> >>
> >>
> >> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
> >> wrote:
> >>>
> >>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
> wrote:
> >>> >
> >>> >
> >>> > On 12 January 2015 at 16:20, Ola Liljedahl <ola.liljedahl@linaro.org
> >
> >>> > wrote:
> >>> >>
> >>> >> Don't report too late timeouts using CU_FAIL as this interferes with
> >>> >> the
> >>> >> cunit
> >>> >> test framework. Just count and report (using LOG_DBG) the number of
> >>> >> late
> >>> >> timeouts.
> >>> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
> the
> >>> >> cunit
> >>> >> test framework.
> >>> >> Don't dereference pointer after successful check for NULL as this
> >>> >> makes
> >>> >> Coverity
> >>> >> complain.
> >>> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> >>> >> Use nanosleep instead of the deprecated usleep.
> >>> >>
> >>> >> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
> >>> >
> >>> >
> >>> > Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
> >>>
> >>> May I suggest splitting this as a patch set?
> >>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a few.
> >>>
> >>> Cheers,
> >>> Anders
> >>>
> >>
> >> I think that although what is considered the correct level of division
> for
> >> a patch is debatable,  following  the rule - "fix one thing per patch"
> bug
> >> fixes should always be their own patch and that is an easily identified
> and
> >> enforced division.
> >> Even if issues did not make it to bugzilla and have a bug ID, the patch
> >> description often tells the story as in this case
> >>
> >> One bug - regression framework
> >> Don't report too late timeouts using CU_FAIL as this interferes with the
> >> cunit
> >> test framework. Just count and report (using LOG_DBG) the number of late
> >> timeouts.  If it had one the BZ ID should be here
> >>
> >> Two bug - static analysis
> >> Don't dereference pointer after successful check for NULL as this makes
> >> Coverity
> >> complain. - should reference the COV: ID for this issue
> >>
> >> Three - clean up to test as per review comments
> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
> >> cunit
> >> test framework.
> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
> >> Use nanosleep instead of the deprecated usleep.
> >>
> >>
> >>
> >>> >
> >>> >>
> >>>
> >>> >> ---
> >>> >> (This document/code contribution attached is provided under the
> terms
> >>> >> of
> >>> >> agreement LES-LTM-21309)
> >>> >>
> >>> >>  test/validation/odp_timer.c | 102
> >>> >> +++++++++++++++++++++++++-------------------
> >>> >>  1 file changed, 59 insertions(+), 43 deletions(-)
> >>> >>
> >>> >> diff --git a/test/validation/odp_timer.c
> b/test/validation/odp_timer.c
> >>> >> index 4c93f71..d893646 100644
> >>> >> --- a/test/validation/odp_timer.c
> >>> >> +++ b/test/validation/odp_timer.c
> >>> >> @@ -8,10 +8,13 @@
> >>> >>   * @file
> >>> >>   */
> >>> >>
> >>> >> -#include <assert.h>
> >>> >> +/* For rand_r and nanosleep */
> >>> >> +#define _POSIX_C_SOURCE 200112L
> >>> >> +#include <time.h>
> >>> >>  #include <unistd.h>
> >>> >>  #include <odp.h>
> >>> >>  #include "odp_cunit_common.h"
> >>> >> +#include "test_debug.h"
> >>> >>
> >>> >>  /** @private Timeout range in milliseconds (ms) */
> >>> >>  #define RANGE_MS 2000
> >>> >> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
> >>> >>  /** @private Timer pool handle used by all threads */
> >>> >>  static odp_timer_pool_t tp;
> >>> >>
> >>> >> +/** @private Count of timeouts delivered too late */
> >>> >> +static odp_atomic_u32_t ndelivtoolate;
> >>> >> +
> >>> >>  /** @private min() function */
> >>> >>  static int min(int a, int b)
> >>> >>  {
> >>> >> @@ -47,8 +53,7 @@ struct test_timer {
> >>> >>  /* @private Handle a received (timeout) buffer */
> >>> >>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
> >>> >> prev_tick)
> >>> >>  {
> >>> >> -       /* Use assert() for internal correctness checks of test
> >>> >> program */
> >>> >> -       assert(buf != ODP_BUFFER_INVALID);
> >>> >> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
> error
> >>> >> */
> >>> >>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
> >>> >>                 /* Not a timeout buffer */
> >>> >>                 CU_FAIL("Unexpected buffer type received");
> >>> >> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
> >>> >> stale,
> >>> >> uint64_t prev_tick)
> >>> >>         if (ttp == NULL)
> >>> >>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
> >>> >>
> >>> >> -       if (ttp->buf2 != buf)
> >>> >> +       if (ttp != NULL && ttp->buf2 != buf)
> >>> >>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
> >>> >> -       if (ttp->tim != tim)
> >>> >> +       if (ttp != NULL && ttp->tim != tim)
> >>> >>                 CU_FAIL("odp_timeout_timer() wrong timer");
> >>> >>         if (stale) {
> >>> >>                 if (odp_timeout_fresh(tmo))
> >>> >>                         CU_FAIL("Wrong status (fresh) for stale
> >>> >> timeout");
> >>> >>                 /* Stale timeout => local timer must have invalid
> tick
> >>> >> */
> >>> >> -               if (ttp->tick != TICK_INVALID)
> >>> >> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
> >>> >>                         CU_FAIL("Stale timeout for active timer");
> >>> >>         } else {
> >>> >>                 if (!odp_timeout_fresh(tmo))
> >>> >>                         CU_FAIL("Wrong status (stale) for fresh
> >>> >> timeout");
> >>> >>                 /* Fresh timeout => local timer must have matching
> >>> >> tick */
> >>> >> -               if (ttp->tick != tick) {
> >>> >> -                       printf("Wrong tick: expected %"PRIu64"
> actual
> >>> >> %"PRIu64"\n",
> >>> >> -                              ttp->tick, tick);
> >>> >> +               if (ttp != NULL && ttp->tick != tick) {
> >>> >> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
> actual
> >>> >> %"PRIu64"\n",
> >>> >> +                               ttp->tick, tick);
> >>> >>                         CU_FAIL("odp_timeout_tick() wrong tick");
> >>> >>                 }
> >>> >>                 /* Check that timeout was delivered 'timely' */
> >>> >>                 if (tick > odp_timer_current_tick(tp))
> >>> >>                         CU_FAIL("Timeout delivered early");
> >>> >>                 if (tick < prev_tick) {
> >>> >> -                       printf("Too late tick: %"PRIu64" prev_tick
> >>> >> %"PRIu64"\n",
> >>> >> -                              tick, prev_tick);
> >>> >> -                       CU_FAIL("Timeout delivered late");
> >>> >> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
> >>> >> %"PRIu64"\n",
> >>> >> +                               tick, prev_tick);
> >>> >> +                       /* We don't report late timeouts using
> CU_FAIL
> >>> >> */
> >>> >> +                       odp_atomic_inc_u32(&ndelivtoolate);
> >>> >>                 }
> >>> >>         }
> >>> >>
> >>> >> -       /* Use assert() for correctness check of test program itself
> >>> >> */
> >>> >> -       assert(ttp->buf == ODP_BUFFER_INVALID);
> >>> >> -       ttp->buf = buf;
> >>> >> +       if (ttp != NULL) {
> >>> >> +               /* Internal error */
> >>> >> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
> >>> >> +               ttp->buf = buf;
> >>> >> +       }
> >>> >>  }
> >>> >>
> >>> >>  /* @private Worker thread entrypoint which performs timer
> >>> >> alloc/set/cancel/free
> >>> >> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
> >>> >>                         /* Save expected expiration tick */
> >>> >>                         tt[i].tick = cur_tick + tck;
> >>> >>                 }
> >>> >> -               if (usleep(1000/*1ms*/) < 0)
> >>> >> -                       perror("usleep"), abort();
> >>> >> +               struct timespec ts;
> >>> >> +               ts.tv_sec = 0;
> >>> >> +               ts.tv_nsec = 1000000; /* 1ms */
> >>> >> +               if (nanosleep(&ts, NULL) < 0)
> >>> >> +                       perror("nanosleep"), abort();
> >>> >>         }
> >>> >>
> >>> >>         /* Cancel and free all timers */
> >>> >> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
> >>> >>                         CU_FAIL("odp_timer_free");
> >>> >>         }
> >>> >>
> >>> >> -       printf("Thread %u: %u timers set\n", thr, nset);
> >>> >> -       printf("Thread %u: %u timers reset\n", thr, nreset);
> >>> >> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
> >>> >> -       printf("Thread %u: %u timers reset/cancelled too late\n",
> >>> >> -              thr, ntoolate);
> >>> >> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
> >>> >> -       printf("Thread %u: %u stale timeout(s) after
> >>> >> odp_timer_free()\n",
> >>> >> -              thr, nstale);
> >>> >> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
> >>> >> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
> >>> >> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
> >>> >> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
> >>> >> +               thr, ntoolate);
> >>> >> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
> >>> >> +       LOG_DBG("Thread %u: %u stale timeout(s) after
> >>> >> odp_timer_free()\n",
> >>> >> +               thr, nstale);
> >>> >>
> >>> >>         /* Delay some more to ensure timeouts for expired timers can
> >>> >> be
> >>> >>          * received */
> >>> >> -       usleep(1000/*1ms*/);
> >>> >> +       struct timespec ts;
> >>> >> +       ts.tv_sec = 0;
> >>> >> +       ts.tv_nsec = 1000000; /* 1ms */
> >>> >> +       if (nanosleep(&ts, NULL) < 0)
> >>> >> +               perror("nanosleep"), abort();
> >>> >>         while (nstale != 0) {
> >>> >>                 odp_buffer_t buf = odp_queue_deq(queue);
> >>> >>                 if (buf != ODP_BUFFER_INVALID) {
> >>> >> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
> >>> >>         if (buf != ODP_BUFFER_INVALID)
> >>> >>                 CU_FAIL("Unexpected buffer received");
> >>> >>
> >>> >> -       printf("Thread %u: exiting\n", thr);
> >>> >> +       LOG_DBG("Thread %u: exiting\n", thr);
> >>> >>         return NULL;
> >>> >>  }
> >>> >>
> >>> >> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
> >>> >>  {
> >>> >>         odp_buffer_pool_param_t params;
> >>> >>         odp_timer_pool_param_t tparam;
> >>> >> -       /* This is a stressfull test - need to reserve some cpu
> cycles
> >>> >> -        * @TODO move to test/performance */
> >>> >> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
> >>> >> +       /* Reserve at least one core for running other processes so
> >>> >> the
> >>> >> timer
> >>> >> +        * test hopefully can run undisturbed and thus get better
> >>> >> timing
> >>> >> +        * results. */
> >>> >> +       int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
> >>> >> +       /* On a single-CPU machine run at least one thread */
> >>> >> +       if (num_workers < 1)
> >>> >> +               num_workers = 1;
> >>> >>
> >>> >>         /* Create timeout buffer pools */
> >>> >>         params.buf_size  = 0;
> >>> >> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
> >>> >>         CU_ASSERT(tpinfo.param.res_ns == RES);
> >>> >>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
> >>> >>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
> >>> >> -       printf("Timer pool\n");
> >>> >> -       printf("----------\n");
> >>> >> -       printf("  name: %s\n", tpinfo.name);
> >>> >> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
> >>> >> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
> >>> >> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
> >>> >> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
> >>> >> -       printf("\n");
> >>> >> -
> >>> >> -       printf("#timers..: %u\n", NTIMERS);
> >>> >> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >>> >> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >>> >> -       printf("\n");
> >>> >> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
> >>> >> +
> >>> >> +       LOG_DBG("#timers..: %u\n", NTIMERS);
> >>> >> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
> >>> >> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
> >>> >>
> >>> >>         uint64_t tick;
> >>> >>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL)
> {
> >>> >> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
> >>> >>         /* Initialize barrier used by worker threads for
> >>> >> synchronization
> >>> >> */
> >>> >>         odp_barrier_init(&test_barrier, num_workers);
> >>> >>
> >>> >> +       /* Initialize the shared timeout counter */
> >>> >> +       odp_atomic_init_u32(&ndelivtoolate, 0);
> >>> >> +
> >>> >>         /* Create and start worker threads */
> >>> >>         pthrd_arg thrdarg;
> >>> >>         thrdarg.testcase = 0;
> >>> >> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
> >>> >>
> >>> >>         /* Wait for worker threads to exit */
> >>> >>         odp_cunit_thread_exit(&thrdarg);
> >>> >> +       LOG_DBG("Number of timeouts delivered/received too late:
> >>> >> %u\n",
> >>> >> +               odp_atomic_load_u32(&ndelivtoolate));
> >>> >>
> >>> >>         /* Check some statistics after the test */
> >>> >>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
> >>> >> --
> >>> >> 1.9.1
> >>> >>
> >>> >>
> >>> >> _______________________________________________
> >>> >> lng-odp mailing list
> >>> >> lng-odp@lists.linaro.org
> >>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
> >>> >
> >>> >
> >>> >
> >>> >
> >>> > --
> >>> > Mike Holmes
> >>> > Linaro  Sr Technical Manager
> >>> > LNG - ODP
> >>> >
> >>> > _______________________________________________
> >>> > lng-odp mailing list
> >>> > lng-odp@lists.linaro.org
> >>> > http://lists.linaro.org/mailman/listinfo/lng-odp
> >>> >
> >>
> >>
> >>
> >>
> >> --
> >> Mike Holmes
> >> Linaro  Sr Technical Manager
> >> LNG - ODP
> >
> >
> >
> >
> > --
> > Mike Holmes
> > Linaro  Sr Technical Manager
> > LNG - ODP
>
Ola Liljedahl Jan. 21, 2015, 6:24 p.m. | #13
On 21 January 2015 at 17:56, Mike Holmes <mike.holmes@linaro.org> wrote:
> I don't see a resolution to the request to break up the patch.
The original patch has been broken up into four independent patches
(you actually reviewed at least one of them and complained on the
usage of perror and abort). I linked to the patches in the delta doc.
What else is missing?

>
>
> On 21 January 2015 at 07:43, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:
>>
>> You have the patches, what are you waiting for?
>>
>> On 20 January 2015 at 17:45, Mike Holmes <mike.holmes@linaro.org> wrote:
>> > This is a blocker since it breaks CI, we need an update the test to not
>> > fail
>> > on discovering that timeouts were late or disable the timer tests with
>> > XFAIL
>> >
>> > On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org> wrote:
>> >>
>> >>
>> >>
>> >> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
>> >> wrote:
>> >>>
>> >>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>> >>> wrote:
>> >>> >
>> >>> >
>> >>> > On 12 January 2015 at 16:20, Ola Liljedahl
>> >>> > <ola.liljedahl@linaro.org>
>> >>> > wrote:
>> >>> >>
>> >>> >> Don't report too late timeouts using CU_FAIL as this interferes
>> >>> >> with
>> >>> >> the
>> >>> >> cunit
>> >>> >> test framework. Just count and report (using LOG_DBG) the number of
>> >>> >> late
>> >>> >> timeouts.
>> >>> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>> >>> >> the
>> >>> >> cunit
>> >>> >> test framework.
>> >>> >> Don't dereference pointer after successful check for NULL as this
>> >>> >> makes
>> >>> >> Coverity
>> >>> >> complain.
>> >>> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>> >>> >> Use nanosleep instead of the deprecated usleep.
>> >>> >>
>> >>> >> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>> >>> >
>> >>> >
>> >>> > Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>> >>>
>> >>> May I suggest splitting this as a patch set?
>> >>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>> >>> few.
>> >>>
>> >>> Cheers,
>> >>> Anders
>> >>>
>> >>
>> >> I think that although what is considered the correct level of division
>> >> for
>> >> a patch is debatable,  following  the rule - "fix one thing per patch"
>> >> bug
>> >> fixes should always be their own patch and that is an easily identified
>> >> and
>> >> enforced division.
>> >> Even if issues did not make it to bugzilla and have a bug ID, the patch
>> >> description often tells the story as in this case
>> >>
>> >> One bug - regression framework
>> >> Don't report too late timeouts using CU_FAIL as this interferes with
>> >> the
>> >> cunit
>> >> test framework. Just count and report (using LOG_DBG) the number of
>> >> late
>> >> timeouts.  If it had one the BZ ID should be here
>> >>
>> >> Two bug - static analysis
>> >> Don't dereference pointer after successful check for NULL as this makes
>> >> Coverity
>> >> complain. - should reference the COV: ID for this issue
>> >>
>> >> Three - clean up to test as per review comments
>> >> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>> >> cunit
>> >> test framework.
>> >> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>> >> Use nanosleep instead of the deprecated usleep.
>> >>
>> >>
>> >>
>> >>> >
>> >>> >>
>> >>>
>> >>> >> ---
>> >>> >> (This document/code contribution attached is provided under the
>> >>> >> terms
>> >>> >> of
>> >>> >> agreement LES-LTM-21309)
>> >>> >>
>> >>> >>  test/validation/odp_timer.c | 102
>> >>> >> +++++++++++++++++++++++++-------------------
>> >>> >>  1 file changed, 59 insertions(+), 43 deletions(-)
>> >>> >>
>> >>> >> diff --git a/test/validation/odp_timer.c
>> >>> >> b/test/validation/odp_timer.c
>> >>> >> index 4c93f71..d893646 100644
>> >>> >> --- a/test/validation/odp_timer.c
>> >>> >> +++ b/test/validation/odp_timer.c
>> >>> >> @@ -8,10 +8,13 @@
>> >>> >>   * @file
>> >>> >>   */
>> >>> >>
>> >>> >> -#include <assert.h>
>> >>> >> +/* For rand_r and nanosleep */
>> >>> >> +#define _POSIX_C_SOURCE 200112L
>> >>> >> +#include <time.h>
>> >>> >>  #include <unistd.h>
>> >>> >>  #include <odp.h>
>> >>> >>  #include "odp_cunit_common.h"
>> >>> >> +#include "test_debug.h"
>> >>> >>
>> >>> >>  /** @private Timeout range in milliseconds (ms) */
>> >>> >>  #define RANGE_MS 2000
>> >>> >> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>> >>> >>  /** @private Timer pool handle used by all threads */
>> >>> >>  static odp_timer_pool_t tp;
>> >>> >>
>> >>> >> +/** @private Count of timeouts delivered too late */
>> >>> >> +static odp_atomic_u32_t ndelivtoolate;
>> >>> >> +
>> >>> >>  /** @private min() function */
>> >>> >>  static int min(int a, int b)
>> >>> >>  {
>> >>> >> @@ -47,8 +53,7 @@ struct test_timer {
>> >>> >>  /* @private Handle a received (timeout) buffer */
>> >>> >>  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>> >>> >> prev_tick)
>> >>> >>  {
>> >>> >> -       /* Use assert() for internal correctness checks of test
>> >>> >> program */
>> >>> >> -       assert(buf != ODP_BUFFER_INVALID);
>> >>> >> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>> >>> >> error
>> >>> >> */
>> >>> >>         if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>> >>> >>                 /* Not a timeout buffer */
>> >>> >>                 CU_FAIL("Unexpected buffer type received");
>> >>> >> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>> >>> >> stale,
>> >>> >> uint64_t prev_tick)
>> >>> >>         if (ttp == NULL)
>> >>> >>                 CU_FAIL("odp_timeout_user_ptr() null user ptr");
>> >>> >>
>> >>> >> -       if (ttp->buf2 != buf)
>> >>> >> +       if (ttp != NULL && ttp->buf2 != buf)
>> >>> >>                 CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>> >>> >> -       if (ttp->tim != tim)
>> >>> >> +       if (ttp != NULL && ttp->tim != tim)
>> >>> >>                 CU_FAIL("odp_timeout_timer() wrong timer");
>> >>> >>         if (stale) {
>> >>> >>                 if (odp_timeout_fresh(tmo))
>> >>> >>                         CU_FAIL("Wrong status (fresh) for stale
>> >>> >> timeout");
>> >>> >>                 /* Stale timeout => local timer must have invalid
>> >>> >> tick
>> >>> >> */
>> >>> >> -               if (ttp->tick != TICK_INVALID)
>> >>> >> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>> >>> >>                         CU_FAIL("Stale timeout for active timer");
>> >>> >>         } else {
>> >>> >>                 if (!odp_timeout_fresh(tmo))
>> >>> >>                         CU_FAIL("Wrong status (stale) for fresh
>> >>> >> timeout");
>> >>> >>                 /* Fresh timeout => local timer must have matching
>> >>> >> tick */
>> >>> >> -               if (ttp->tick != tick) {
>> >>> >> -                       printf("Wrong tick: expected %"PRIu64"
>> >>> >> actual
>> >>> >> %"PRIu64"\n",
>> >>> >> -                              ttp->tick, tick);
>> >>> >> +               if (ttp != NULL && ttp->tick != tick) {
>> >>> >> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>> >>> >> actual
>> >>> >> %"PRIu64"\n",
>> >>> >> +                               ttp->tick, tick);
>> >>> >>                         CU_FAIL("odp_timeout_tick() wrong tick");
>> >>> >>                 }
>> >>> >>                 /* Check that timeout was delivered 'timely' */
>> >>> >>                 if (tick > odp_timer_current_tick(tp))
>> >>> >>                         CU_FAIL("Timeout delivered early");
>> >>> >>                 if (tick < prev_tick) {
>> >>> >> -                       printf("Too late tick: %"PRIu64" prev_tick
>> >>> >> %"PRIu64"\n",
>> >>> >> -                              tick, prev_tick);
>> >>> >> -                       CU_FAIL("Timeout delivered late");
>> >>> >> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>> >>> >> %"PRIu64"\n",
>> >>> >> +                               tick, prev_tick);
>> >>> >> +                       /* We don't report late timeouts using
>> >>> >> CU_FAIL
>> >>> >> */
>> >>> >> +                       odp_atomic_inc_u32(&ndelivtoolate);
>> >>> >>                 }
>> >>> >>         }
>> >>> >>
>> >>> >> -       /* Use assert() for correctness check of test program
>> >>> >> itself
>> >>> >> */
>> >>> >> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>> >>> >> -       ttp->buf = buf;
>> >>> >> +       if (ttp != NULL) {
>> >>> >> +               /* Internal error */
>> >>> >> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>> >>> >> +               ttp->buf = buf;
>> >>> >> +       }
>> >>> >>  }
>> >>> >>
>> >>> >>  /* @private Worker thread entrypoint which performs timer
>> >>> >> alloc/set/cancel/free
>> >>> >> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>> >>> >>                         /* Save expected expiration tick */
>> >>> >>                         tt[i].tick = cur_tick + tck;
>> >>> >>                 }
>> >>> >> -               if (usleep(1000/*1ms*/) < 0)
>> >>> >> -                       perror("usleep"), abort();
>> >>> >> +               struct timespec ts;
>> >>> >> +               ts.tv_sec = 0;
>> >>> >> +               ts.tv_nsec = 1000000; /* 1ms */
>> >>> >> +               if (nanosleep(&ts, NULL) < 0)
>> >>> >> +                       perror("nanosleep"), abort();
>> >>> >>         }
>> >>> >>
>> >>> >>         /* Cancel and free all timers */
>> >>> >> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>> >>> >>                         CU_FAIL("odp_timer_free");
>> >>> >>         }
>> >>> >>
>> >>> >> -       printf("Thread %u: %u timers set\n", thr, nset);
>> >>> >> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>> >>> >> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>> >>> >> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>> >>> >> -              thr, ntoolate);
>> >>> >> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>> >>> >> -       printf("Thread %u: %u stale timeout(s) after
>> >>> >> odp_timer_free()\n",
>> >>> >> -              thr, nstale);
>> >>> >> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>> >>> >> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>> >>> >> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>> >>> >> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>> >>> >> +               thr, ntoolate);
>> >>> >> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>> >>> >> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>> >>> >> odp_timer_free()\n",
>> >>> >> +               thr, nstale);
>> >>> >>
>> >>> >>         /* Delay some more to ensure timeouts for expired timers
>> >>> >> can
>> >>> >> be
>> >>> >>          * received */
>> >>> >> -       usleep(1000/*1ms*/);
>> >>> >> +       struct timespec ts;
>> >>> >> +       ts.tv_sec = 0;
>> >>> >> +       ts.tv_nsec = 1000000; /* 1ms */
>> >>> >> +       if (nanosleep(&ts, NULL) < 0)
>> >>> >> +               perror("nanosleep"), abort();
>> >>> >>         while (nstale != 0) {
>> >>> >>                 odp_buffer_t buf = odp_queue_deq(queue);
>> >>> >>                 if (buf != ODP_BUFFER_INVALID) {
>> >>> >> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>> >>> >>         if (buf != ODP_BUFFER_INVALID)
>> >>> >>                 CU_FAIL("Unexpected buffer received");
>> >>> >>
>> >>> >> -       printf("Thread %u: exiting\n", thr);
>> >>> >> +       LOG_DBG("Thread %u: exiting\n", thr);
>> >>> >>         return NULL;
>> >>> >>  }
>> >>> >>
>> >>> >> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>> >>> >>  {
>> >>> >>         odp_buffer_pool_param_t params;
>> >>> >>         odp_timer_pool_param_t tparam;
>> >>> >> -       /* This is a stressfull test - need to reserve some cpu
>> >>> >> cycles
>> >>> >> -        * @TODO move to test/performance */
>> >>> >> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>> >>> >> +       /* Reserve at least one core for running other processes so
>> >>> >> the
>> >>> >> timer
>> >>> >> +        * test hopefully can run undisturbed and thus get better
>> >>> >> timing
>> >>> >> +        * results. */
>> >>> >> +       int num_workers = min(odp_sys_cpu_count() - 1,
>> >>> >> MAX_WORKERS);
>> >>> >> +       /* On a single-CPU machine run at least one thread */
>> >>> >> +       if (num_workers < 1)
>> >>> >> +               num_workers = 1;
>> >>> >>
>> >>> >>         /* Create timeout buffer pools */
>> >>> >>         params.buf_size  = 0;
>> >>> >> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>> >>> >>         CU_ASSERT(tpinfo.param.res_ns == RES);
>> >>> >>         CU_ASSERT(tpinfo.param.min_tmo == MIN);
>> >>> >>         CU_ASSERT(tpinfo.param.max_tmo == MAX);
>> >>> >> -       printf("Timer pool\n");
>> >>> >> -       printf("----------\n");
>> >>> >> -       printf("  name: %s\n", tpinfo.name);
>> >>> >> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>> >>> >> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>> >>> >> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>> >>> >> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>> >>> >> -       printf("\n");
>> >>> >> -
>> >>> >> -       printf("#timers..: %u\n", NTIMERS);
>> >>> >> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> >>> >> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>> >>> >> -       printf("\n");
>> >>> >> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>> >>> >> +
>> >>> >> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>> >>> >> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>> >>> >> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>> >>> >>
>> >>> >>         uint64_t tick;
>> >>> >>         for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL)
>> >>> >> {
>> >>> >> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>> >>> >>         /* Initialize barrier used by worker threads for
>> >>> >> synchronization
>> >>> >> */
>> >>> >>         odp_barrier_init(&test_barrier, num_workers);
>> >>> >>
>> >>> >> +       /* Initialize the shared timeout counter */
>> >>> >> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>> >>> >> +
>> >>> >>         /* Create and start worker threads */
>> >>> >>         pthrd_arg thrdarg;
>> >>> >>         thrdarg.testcase = 0;
>> >>> >> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>> >>> >>
>> >>> >>         /* Wait for worker threads to exit */
>> >>> >>         odp_cunit_thread_exit(&thrdarg);
>> >>> >> +       LOG_DBG("Number of timeouts delivered/received too late:
>> >>> >> %u\n",
>> >>> >> +               odp_atomic_load_u32(&ndelivtoolate));
>> >>> >>
>> >>> >>         /* Check some statistics after the test */
>> >>> >>         if (odp_timer_pool_info(tp, &tpinfo) != 0)
>> >>> >> --
>> >>> >> 1.9.1
>> >>> >>
>> >>> >>
>> >>> >> _______________________________________________
>> >>> >> lng-odp mailing list
>> >>> >> lng-odp@lists.linaro.org
>> >>> >> http://lists.linaro.org/mailman/listinfo/lng-odp
>> >>> >
>> >>> >
>> >>> >
>> >>> >
>> >>> > --
>> >>> > Mike Holmes
>> >>> > Linaro  Sr Technical Manager
>> >>> > LNG - ODP
>> >>> >
>> >>> > _______________________________________________
>> >>> > lng-odp mailing list
>> >>> > lng-odp@lists.linaro.org
>> >>> > http://lists.linaro.org/mailman/listinfo/lng-odp
>> >>> >
>> >>
>> >>
>> >>
>> >>
>> >> --
>> >> Mike Holmes
>> >> Linaro  Sr Technical Manager
>> >> LNG - ODP
>> >
>> >
>> >
>> >
>> > --
>> > Mike Holmes
>> > Linaro  Sr Technical Manager
>> > LNG - ODP
>
>
>
>
> --
> Mike Holmes
> Linaro  Sr Technical Manager
> LNG - ODP
Maxim Uvarov Jan. 23, 2015, 11:19 a.m. | #14
Anders you added comment to break this patch on two. How is it critical 
for now?

Maxim.

On 01/21/2015 09:24 PM, Ola Liljedahl wrote:
> On 21 January 2015 at 17:56, Mike Holmes <mike.holmes@linaro.org> wrote:
>> I don't see a resolution to the request to break up the patch.
> The original patch has been broken up into four independent patches
> (you actually reviewed at least one of them and complained on the
> usage of perror and abort). I linked to the patches in the delta doc.
> What else is missing?
>
>>
>> On 21 January 2015 at 07:43, Ola Liljedahl <ola.liljedahl@linaro.org> wrote:
>>> You have the patches, what are you waiting for?
>>>
>>> On 20 January 2015 at 17:45, Mike Holmes <mike.holmes@linaro.org> wrote:
>>>> This is a blocker since it breaks CI, we need an update the test to not
>>>> fail
>>>> on discovering that timeouts were late or disable the timer tests with
>>>> XFAIL
>>>>
>>>> On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org> wrote:
>>>>>
>>>>>
>>>>> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
>>>>> wrote:
>>>>>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>>>>> wrote:
>>>>>>>
>>>>>>> On 12 January 2015 at 16:20, Ola Liljedahl
>>>>>>> <ola.liljedahl@linaro.org>
>>>>>>> wrote:
>>>>>>>> Don't report too late timeouts using CU_FAIL as this interferes
>>>>>>>> with
>>>>>>>> the
>>>>>>>> cunit
>>>>>>>> test framework. Just count and report (using LOG_DBG) the number of
>>>>>>>> late
>>>>>>>> timeouts.
>>>>>>>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>>>>>>>> the
>>>>>>>> cunit
>>>>>>>> test framework.
>>>>>>>> Don't dereference pointer after successful check for NULL as this
>>>>>>>> makes
>>>>>>>> Coverity
>>>>>>>> complain.
>>>>>>>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>>>>> Use nanosleep instead of the deprecated usleep.
>>>>>>>>
>>>>>>>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>>>>>>
>>>>>>> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>>>> May I suggest splitting this as a patch set?
>>>>>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>>>>>> few.
>>>>>>
>>>>>> Cheers,
>>>>>> Anders
>>>>>>
>>>>> I think that although what is considered the correct level of division
>>>>> for
>>>>> a patch is debatable,  following  the rule - "fix one thing per patch"
>>>>> bug
>>>>> fixes should always be their own patch and that is an easily identified
>>>>> and
>>>>> enforced division.
>>>>> Even if issues did not make it to bugzilla and have a bug ID, the patch
>>>>> description often tells the story as in this case
>>>>>
>>>>> One bug - regression framework
>>>>> Don't report too late timeouts using CU_FAIL as this interferes with
>>>>> the
>>>>> cunit
>>>>> test framework. Just count and report (using LOG_DBG) the number of
>>>>> late
>>>>> timeouts.  If it had one the BZ ID should be here
>>>>>
>>>>> Two bug - static analysis
>>>>> Don't dereference pointer after successful check for NULL as this makes
>>>>> Coverity
>>>>> complain. - should reference the COV: ID for this issue
>>>>>
>>>>> Three - clean up to test as per review comments
>>>>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>>>>> cunit
>>>>> test framework.
>>>>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>> Use nanosleep instead of the deprecated usleep.
>>>>>
>>>>>
>>>>>
>>>>>>>> ---
>>>>>>>> (This document/code contribution attached is provided under the
>>>>>>>> terms
>>>>>>>> of
>>>>>>>> agreement LES-LTM-21309)
>>>>>>>>
>>>>>>>>   test/validation/odp_timer.c | 102
>>>>>>>> +++++++++++++++++++++++++-------------------
>>>>>>>>   1 file changed, 59 insertions(+), 43 deletions(-)
>>>>>>>>
>>>>>>>> diff --git a/test/validation/odp_timer.c
>>>>>>>> b/test/validation/odp_timer.c
>>>>>>>> index 4c93f71..d893646 100644
>>>>>>>> --- a/test/validation/odp_timer.c
>>>>>>>> +++ b/test/validation/odp_timer.c
>>>>>>>> @@ -8,10 +8,13 @@
>>>>>>>>    * @file
>>>>>>>>    */
>>>>>>>>
>>>>>>>> -#include <assert.h>
>>>>>>>> +/* For rand_r and nanosleep */
>>>>>>>> +#define _POSIX_C_SOURCE 200112L
>>>>>>>> +#include <time.h>
>>>>>>>>   #include <unistd.h>
>>>>>>>>   #include <odp.h>
>>>>>>>>   #include "odp_cunit_common.h"
>>>>>>>> +#include "test_debug.h"
>>>>>>>>
>>>>>>>>   /** @private Timeout range in milliseconds (ms) */
>>>>>>>>   #define RANGE_MS 2000
>>>>>>>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>>>>>>   /** @private Timer pool handle used by all threads */
>>>>>>>>   static odp_timer_pool_t tp;
>>>>>>>>
>>>>>>>> +/** @private Count of timeouts delivered too late */
>>>>>>>> +static odp_atomic_u32_t ndelivtoolate;
>>>>>>>> +
>>>>>>>>   /** @private min() function */
>>>>>>>>   static int min(int a, int b)
>>>>>>>>   {
>>>>>>>> @@ -47,8 +53,7 @@ struct test_timer {
>>>>>>>>   /* @private Handle a received (timeout) buffer */
>>>>>>>>   static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>>>>>>> prev_tick)
>>>>>>>>   {
>>>>>>>> -       /* Use assert() for internal correctness checks of test
>>>>>>>> program */
>>>>>>>> -       assert(buf != ODP_BUFFER_INVALID);
>>>>>>>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>>>>>>> error
>>>>>>>> */
>>>>>>>>          if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>>>>>>                  /* Not a timeout buffer */
>>>>>>>>                  CU_FAIL("Unexpected buffer type received");
>>>>>>>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>>>>>>> stale,
>>>>>>>> uint64_t prev_tick)
>>>>>>>>          if (ttp == NULL)
>>>>>>>>                  CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>>>>>>
>>>>>>>> -       if (ttp->buf2 != buf)
>>>>>>>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>>>>>>                  CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>>>>>>> -       if (ttp->tim != tim)
>>>>>>>> +       if (ttp != NULL && ttp->tim != tim)
>>>>>>>>                  CU_FAIL("odp_timeout_timer() wrong timer");
>>>>>>>>          if (stale) {
>>>>>>>>                  if (odp_timeout_fresh(tmo))
>>>>>>>>                          CU_FAIL("Wrong status (fresh) for stale
>>>>>>>> timeout");
>>>>>>>>                  /* Stale timeout => local timer must have invalid
>>>>>>>> tick
>>>>>>>> */
>>>>>>>> -               if (ttp->tick != TICK_INVALID)
>>>>>>>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>>>>>>                          CU_FAIL("Stale timeout for active timer");
>>>>>>>>          } else {
>>>>>>>>                  if (!odp_timeout_fresh(tmo))
>>>>>>>>                          CU_FAIL("Wrong status (stale) for fresh
>>>>>>>> timeout");
>>>>>>>>                  /* Fresh timeout => local timer must have matching
>>>>>>>> tick */
>>>>>>>> -               if (ttp->tick != tick) {
>>>>>>>> -                       printf("Wrong tick: expected %"PRIu64"
>>>>>>>> actual
>>>>>>>> %"PRIu64"\n",
>>>>>>>> -                              ttp->tick, tick);
>>>>>>>> +               if (ttp != NULL && ttp->tick != tick) {
>>>>>>>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>>>>>>> actual
>>>>>>>> %"PRIu64"\n",
>>>>>>>> +                               ttp->tick, tick);
>>>>>>>>                          CU_FAIL("odp_timeout_tick() wrong tick");
>>>>>>>>                  }
>>>>>>>>                  /* Check that timeout was delivered 'timely' */
>>>>>>>>                  if (tick > odp_timer_current_tick(tp))
>>>>>>>>                          CU_FAIL("Timeout delivered early");
>>>>>>>>                  if (tick < prev_tick) {
>>>>>>>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>>>>>>> %"PRIu64"\n",
>>>>>>>> -                              tick, prev_tick);
>>>>>>>> -                       CU_FAIL("Timeout delivered late");
>>>>>>>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>>>>>>> %"PRIu64"\n",
>>>>>>>> +                               tick, prev_tick);
>>>>>>>> +                       /* We don't report late timeouts using
>>>>>>>> CU_FAIL
>>>>>>>> */
>>>>>>>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>>>>>>                  }
>>>>>>>>          }
>>>>>>>>
>>>>>>>> -       /* Use assert() for correctness check of test program
>>>>>>>> itself
>>>>>>>> */
>>>>>>>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>>> -       ttp->buf = buf;
>>>>>>>> +       if (ttp != NULL) {
>>>>>>>> +               /* Internal error */
>>>>>>>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>>> +               ttp->buf = buf;
>>>>>>>> +       }
>>>>>>>>   }
>>>>>>>>
>>>>>>>>   /* @private Worker thread entrypoint which performs timer
>>>>>>>> alloc/set/cancel/free
>>>>>>>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>                          /* Save expected expiration tick */
>>>>>>>>                          tt[i].tick = cur_tick + tck;
>>>>>>>>                  }
>>>>>>>> -               if (usleep(1000/*1ms*/) < 0)
>>>>>>>> -                       perror("usleep"), abort();
>>>>>>>> +               struct timespec ts;
>>>>>>>> +               ts.tv_sec = 0;
>>>>>>>> +               ts.tv_nsec = 1000000; /* 1ms */
>>>>>>>> +               if (nanosleep(&ts, NULL) < 0)
>>>>>>>> +                       perror("nanosleep"), abort();
>>>>>>>>          }
>>>>>>>>
>>>>>>>>          /* Cancel and free all timers */
>>>>>>>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>                          CU_FAIL("odp_timer_free");
>>>>>>>>          }
>>>>>>>>
>>>>>>>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>>>>>>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>>>>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>>>>>>> -              thr, ntoolate);
>>>>>>>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>>> -       printf("Thread %u: %u stale timeout(s) after
>>>>>>>> odp_timer_free()\n",
>>>>>>>> -              thr, nstale);
>>>>>>>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>>>>>>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>>>>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>>>>>>> +               thr, ntoolate);
>>>>>>>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>>>>>>> odp_timer_free()\n",
>>>>>>>> +               thr, nstale);
>>>>>>>>
>>>>>>>>          /* Delay some more to ensure timeouts for expired timers
>>>>>>>> can
>>>>>>>> be
>>>>>>>>           * received */
>>>>>>>> -       usleep(1000/*1ms*/);
>>>>>>>> +       struct timespec ts;
>>>>>>>> +       ts.tv_sec = 0;
>>>>>>>> +       ts.tv_nsec = 1000000; /* 1ms */
>>>>>>>> +       if (nanosleep(&ts, NULL) < 0)
>>>>>>>> +               perror("nanosleep"), abort();
>>>>>>>>          while (nstale != 0) {
>>>>>>>>                  odp_buffer_t buf = odp_queue_deq(queue);
>>>>>>>>                  if (buf != ODP_BUFFER_INVALID) {
>>>>>>>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>          if (buf != ODP_BUFFER_INVALID)
>>>>>>>>                  CU_FAIL("Unexpected buffer received");
>>>>>>>>
>>>>>>>> -       printf("Thread %u: exiting\n", thr);
>>>>>>>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>>>>>>          return NULL;
>>>>>>>>   }
>>>>>>>>
>>>>>>>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>>>>>>   {
>>>>>>>>          odp_buffer_pool_param_t params;
>>>>>>>>          odp_timer_pool_param_t tparam;
>>>>>>>> -       /* This is a stressfull test - need to reserve some cpu
>>>>>>>> cycles
>>>>>>>> -        * @TODO move to test/performance */
>>>>>>>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>>>>>>> +       /* Reserve at least one core for running other processes so
>>>>>>>> the
>>>>>>>> timer
>>>>>>>> +        * test hopefully can run undisturbed and thus get better
>>>>>>>> timing
>>>>>>>> +        * results. */
>>>>>>>> +       int num_workers = min(odp_sys_cpu_count() - 1,
>>>>>>>> MAX_WORKERS);
>>>>>>>> +       /* On a single-CPU machine run at least one thread */
>>>>>>>> +       if (num_workers < 1)
>>>>>>>> +               num_workers = 1;
>>>>>>>>
>>>>>>>>          /* Create timeout buffer pools */
>>>>>>>>          params.buf_size  = 0;
>>>>>>>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>>>>>>          CU_ASSERT(tpinfo.param.res_ns == RES);
>>>>>>>>          CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>>>>>>          CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>>>>>>> -       printf("Timer pool\n");
>>>>>>>> -       printf("----------\n");
>>>>>>>> -       printf("  name: %s\n", tpinfo.name);
>>>>>>>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>>>>>>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>>>>>>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>>>>>>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>>>>>>> -       printf("\n");
>>>>>>>> -
>>>>>>>> -       printf("#timers..: %u\n", NTIMERS);
>>>>>>>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>>> -       printf("\n");
>>>>>>>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>>>>>>> +
>>>>>>>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>>>>>>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>>>
>>>>>>>>          uint64_t tick;
>>>>>>>>          for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL)
>>>>>>>> {
>>>>>>>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>>>>>>          /* Initialize barrier used by worker threads for
>>>>>>>> synchronization
>>>>>>>> */
>>>>>>>>          odp_barrier_init(&test_barrier, num_workers);
>>>>>>>>
>>>>>>>> +       /* Initialize the shared timeout counter */
>>>>>>>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>>>>>>> +
>>>>>>>>          /* Create and start worker threads */
>>>>>>>>          pthrd_arg thrdarg;
>>>>>>>>          thrdarg.testcase = 0;
>>>>>>>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>>>>>>
>>>>>>>>          /* Wait for worker threads to exit */
>>>>>>>>          odp_cunit_thread_exit(&thrdarg);
>>>>>>>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>>>>>>> %u\n",
>>>>>>>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>>>>>>
>>>>>>>>          /* Check some statistics after the test */
>>>>>>>>          if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>>>>>>> --
>>>>>>>> 1.9.1
>>>>>>>>
>>>>>>>>
>>>>>>>> _______________________________________________
>>>>>>>> lng-odp mailing list
>>>>>>>> lng-odp@lists.linaro.org
>>>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> Mike Holmes
>>>>>>> Linaro  Sr Technical Manager
>>>>>>> LNG - ODP
>>>>>>>
>>>>>>> _______________________________________________
>>>>>>> lng-odp mailing list
>>>>>>> lng-odp@lists.linaro.org
>>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Mike Holmes
>>>>> Linaro  Sr Technical Manager
>>>>> LNG - ODP
>>>>
>>>>
>>>>
>>>> --
>>>> Mike Holmes
>>>> Linaro  Sr Technical Manager
>>>> LNG - ODP
>>
>>
>>
>> --
>> Mike Holmes
>> Linaro  Sr Technical Manager
>> LNG - ODP
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp
Ola Liljedahl Jan. 23, 2015, 1:55 p.m. | #15
On 23 January 2015 at 11:19, Maxim Uvarov <maxim.uvarov@linaro.org> wrote:
> Anders you added comment to break this patch on two. How is it critical for
> now?
There is a v2 of this patch that has been broken into four separate patches.
The links are in the delta document.

>
> Maxim.
>
> On 01/21/2015 09:24 PM, Ola Liljedahl wrote:
>>
>> On 21 January 2015 at 17:56, Mike Holmes <mike.holmes@linaro.org> wrote:
>>>
>>> I don't see a resolution to the request to break up the patch.
>>
>> The original patch has been broken up into four independent patches
>> (you actually reviewed at least one of them and complained on the
>> usage of perror and abort). I linked to the patches in the delta doc.
>> What else is missing?
>>
>>>
>>> On 21 January 2015 at 07:43, Ola Liljedahl <ola.liljedahl@linaro.org>
>>> wrote:
>>>>
>>>> You have the patches, what are you waiting for?
>>>>
>>>> On 20 January 2015 at 17:45, Mike Holmes <mike.holmes@linaro.org> wrote:
>>>>>
>>>>> This is a blocker since it breaks CI, we need an update the test to not
>>>>> fail
>>>>> on discovering that timeouts were late or disable the timer tests with
>>>>> XFAIL
>>>>>
>>>>> On 16 January 2015 at 08:49, Mike Holmes <mike.holmes@linaro.org>
>>>>> wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 13 January 2015 at 18:27, Anders Roxell <anders.roxell@linaro.org>
>>>>>> wrote:
>>>>>>>
>>>>>>> On 13 January 2015 at 20:15, Mike Holmes <mike.holmes@linaro.org>
>>>>>>> wrote:
>>>>>>>>
>>>>>>>>
>>>>>>>> On 12 January 2015 at 16:20, Ola Liljedahl
>>>>>>>> <ola.liljedahl@linaro.org>
>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> Don't report too late timeouts using CU_FAIL as this interferes
>>>>>>>>> with
>>>>>>>>> the
>>>>>>>>> cunit
>>>>>>>>> test framework. Just count and report (using LOG_DBG) the number of
>>>>>>>>> late
>>>>>>>>> timeouts.
>>>>>>>>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with
>>>>>>>>> the
>>>>>>>>> cunit
>>>>>>>>> test framework.
>>>>>>>>> Don't dereference pointer after successful check for NULL as this
>>>>>>>>> makes
>>>>>>>>> Coverity
>>>>>>>>> complain.
>>>>>>>>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>>>>>> Use nanosleep instead of the deprecated usleep.
>>>>>>>>>
>>>>>>>>> Signed-off-by: Ola Liljedahl <ola.liljedahl@linaro.org>
>>>>>>>>
>>>>>>>>
>>>>>>>> Reviewed-and-tested-by: Mike Holmes <mike.holmes@linaro.org>
>>>>>>>
>>>>>>> May I suggest splitting this as a patch set?
>>>>>>> one patch for ODP_DBG, one for nanosleep, CU_ASSERT_FAIL to name a
>>>>>>> few.
>>>>>>>
>>>>>>> Cheers,
>>>>>>> Anders
>>>>>>>
>>>>>> I think that although what is considered the correct level of division
>>>>>> for
>>>>>> a patch is debatable,  following  the rule - "fix one thing per patch"
>>>>>> bug
>>>>>> fixes should always be their own patch and that is an easily
>>>>>> identified
>>>>>> and
>>>>>> enforced division.
>>>>>> Even if issues did not make it to bugzilla and have a bug ID, the
>>>>>> patch
>>>>>> description often tells the story as in this case
>>>>>>
>>>>>> One bug - regression framework
>>>>>> Don't report too late timeouts using CU_FAIL as this interferes with
>>>>>> the
>>>>>> cunit
>>>>>> test framework. Just count and report (using LOG_DBG) the number of
>>>>>> late
>>>>>> timeouts.  If it had one the BZ ID should be here
>>>>>>
>>>>>> Two bug - static analysis
>>>>>> Don't dereference pointer after successful check for NULL as this
>>>>>> makes
>>>>>> Coverity
>>>>>> complain. - should reference the COV: ID for this issue
>>>>>>
>>>>>> Three - clean up to test as per review comments
>>>>>> Use CU_ASSERT_FATAL instead of plain assert so to work wither with the
>>>>>> cunit
>>>>>> test framework.
>>>>>> Use LOG_DBG instead of printf. Remove some unnecessary printouts.
>>>>>> Use nanosleep instead of the deprecated usleep.
>>>>>>
>>>>>>
>>>>>>
>>>>>>>>> ---
>>>>>>>>> (This document/code contribution attached is provided under the
>>>>>>>>> terms
>>>>>>>>> of
>>>>>>>>> agreement LES-LTM-21309)
>>>>>>>>>
>>>>>>>>>   test/validation/odp_timer.c | 102
>>>>>>>>> +++++++++++++++++++++++++-------------------
>>>>>>>>>   1 file changed, 59 insertions(+), 43 deletions(-)
>>>>>>>>>
>>>>>>>>> diff --git a/test/validation/odp_timer.c
>>>>>>>>> b/test/validation/odp_timer.c
>>>>>>>>> index 4c93f71..d893646 100644
>>>>>>>>> --- a/test/validation/odp_timer.c
>>>>>>>>> +++ b/test/validation/odp_timer.c
>>>>>>>>> @@ -8,10 +8,13 @@
>>>>>>>>>    * @file
>>>>>>>>>    */
>>>>>>>>>
>>>>>>>>> -#include <assert.h>
>>>>>>>>> +/* For rand_r and nanosleep */
>>>>>>>>> +#define _POSIX_C_SOURCE 200112L
>>>>>>>>> +#include <time.h>
>>>>>>>>>   #include <unistd.h>
>>>>>>>>>   #include <odp.h>
>>>>>>>>>   #include "odp_cunit_common.h"
>>>>>>>>> +#include "test_debug.h"
>>>>>>>>>
>>>>>>>>>   /** @private Timeout range in milliseconds (ms) */
>>>>>>>>>   #define RANGE_MS 2000
>>>>>>>>> @@ -28,6 +31,9 @@ static odp_buffer_pool_t tbp;
>>>>>>>>>   /** @private Timer pool handle used by all threads */
>>>>>>>>>   static odp_timer_pool_t tp;
>>>>>>>>>
>>>>>>>>> +/** @private Count of timeouts delivered too late */
>>>>>>>>> +static odp_atomic_u32_t ndelivtoolate;
>>>>>>>>> +
>>>>>>>>>   /** @private min() function */
>>>>>>>>>   static int min(int a, int b)
>>>>>>>>>   {
>>>>>>>>> @@ -47,8 +53,7 @@ struct test_timer {
>>>>>>>>>   /* @private Handle a received (timeout) buffer */
>>>>>>>>>   static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t
>>>>>>>>> prev_tick)
>>>>>>>>>   {
>>>>>>>>> -       /* Use assert() for internal correctness checks of test
>>>>>>>>> program */
>>>>>>>>> -       assert(buf != ODP_BUFFER_INVALID);
>>>>>>>>> +       CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal
>>>>>>>>> error
>>>>>>>>> */
>>>>>>>>>          if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
>>>>>>>>>                  /* Not a timeout buffer */
>>>>>>>>>                  CU_FAIL("Unexpected buffer type received");
>>>>>>>>> @@ -65,38 +70,41 @@ static void handle_tmo(odp_buffer_t buf, bool
>>>>>>>>> stale,
>>>>>>>>> uint64_t prev_tick)
>>>>>>>>>          if (ttp == NULL)
>>>>>>>>>                  CU_FAIL("odp_timeout_user_ptr() null user ptr");
>>>>>>>>>
>>>>>>>>> -       if (ttp->buf2 != buf)
>>>>>>>>> +       if (ttp != NULL && ttp->buf2 != buf)
>>>>>>>>>                  CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
>>>>>>>>> -       if (ttp->tim != tim)
>>>>>>>>> +       if (ttp != NULL && ttp->tim != tim)
>>>>>>>>>                  CU_FAIL("odp_timeout_timer() wrong timer");
>>>>>>>>>          if (stale) {
>>>>>>>>>                  if (odp_timeout_fresh(tmo))
>>>>>>>>>                          CU_FAIL("Wrong status (fresh) for stale
>>>>>>>>> timeout");
>>>>>>>>>                  /* Stale timeout => local timer must have invalid
>>>>>>>>> tick
>>>>>>>>> */
>>>>>>>>> -               if (ttp->tick != TICK_INVALID)
>>>>>>>>> +               if (ttp != NULL && ttp->tick != TICK_INVALID)
>>>>>>>>>                          CU_FAIL("Stale timeout for active timer");
>>>>>>>>>          } else {
>>>>>>>>>                  if (!odp_timeout_fresh(tmo))
>>>>>>>>>                          CU_FAIL("Wrong status (stale) for fresh
>>>>>>>>> timeout");
>>>>>>>>>                  /* Fresh timeout => local timer must have matching
>>>>>>>>> tick */
>>>>>>>>> -               if (ttp->tick != tick) {
>>>>>>>>> -                       printf("Wrong tick: expected %"PRIu64"
>>>>>>>>> actual
>>>>>>>>> %"PRIu64"\n",
>>>>>>>>> -                              ttp->tick, tick);
>>>>>>>>> +               if (ttp != NULL && ttp->tick != tick) {
>>>>>>>>> +                       LOG_DBG("Wrong tick: expected %"PRIu64"
>>>>>>>>> actual
>>>>>>>>> %"PRIu64"\n",
>>>>>>>>> +                               ttp->tick, tick);
>>>>>>>>>                          CU_FAIL("odp_timeout_tick() wrong tick");
>>>>>>>>>                  }
>>>>>>>>>                  /* Check that timeout was delivered 'timely' */
>>>>>>>>>                  if (tick > odp_timer_current_tick(tp))
>>>>>>>>>                          CU_FAIL("Timeout delivered early");
>>>>>>>>>                  if (tick < prev_tick) {
>>>>>>>>> -                       printf("Too late tick: %"PRIu64" prev_tick
>>>>>>>>> %"PRIu64"\n",
>>>>>>>>> -                              tick, prev_tick);
>>>>>>>>> -                       CU_FAIL("Timeout delivered late");
>>>>>>>>> +                       LOG_DBG("Too late tick: %"PRIu64" prev_tick
>>>>>>>>> %"PRIu64"\n",
>>>>>>>>> +                               tick, prev_tick);
>>>>>>>>> +                       /* We don't report late timeouts using
>>>>>>>>> CU_FAIL
>>>>>>>>> */
>>>>>>>>> +                       odp_atomic_inc_u32(&ndelivtoolate);
>>>>>>>>>                  }
>>>>>>>>>          }
>>>>>>>>>
>>>>>>>>> -       /* Use assert() for correctness check of test program
>>>>>>>>> itself
>>>>>>>>> */
>>>>>>>>> -       assert(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>>>> -       ttp->buf = buf;
>>>>>>>>> +       if (ttp != NULL) {
>>>>>>>>> +               /* Internal error */
>>>>>>>>> +               CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
>>>>>>>>> +               ttp->buf = buf;
>>>>>>>>> +       }
>>>>>>>>>   }
>>>>>>>>>
>>>>>>>>>   /* @private Worker thread entrypoint which performs timer
>>>>>>>>> alloc/set/cancel/free
>>>>>>>>> @@ -203,8 +211,11 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>>                          /* Save expected expiration tick */
>>>>>>>>>                          tt[i].tick = cur_tick + tck;
>>>>>>>>>                  }
>>>>>>>>> -               if (usleep(1000/*1ms*/) < 0)
>>>>>>>>> -                       perror("usleep"), abort();
>>>>>>>>> +               struct timespec ts;
>>>>>>>>> +               ts.tv_sec = 0;
>>>>>>>>> +               ts.tv_nsec = 1000000; /* 1ms */
>>>>>>>>> +               if (nanosleep(&ts, NULL) < 0)
>>>>>>>>> +                       perror("nanosleep"), abort();
>>>>>>>>>          }
>>>>>>>>>
>>>>>>>>>          /* Cancel and free all timers */
>>>>>>>>> @@ -220,18 +231,22 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>>                          CU_FAIL("odp_timer_free");
>>>>>>>>>          }
>>>>>>>>>
>>>>>>>>> -       printf("Thread %u: %u timers set\n", thr, nset);
>>>>>>>>> -       printf("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>>>> -       printf("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>>>>>> -       printf("Thread %u: %u timers reset/cancelled too late\n",
>>>>>>>>> -              thr, ntoolate);
>>>>>>>>> -       printf("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>>>> -       printf("Thread %u: %u stale timeout(s) after
>>>>>>>>> odp_timer_free()\n",
>>>>>>>>> -              thr, nstale);
>>>>>>>>> +       LOG_DBG("Thread %u: %u timers set\n", thr, nset);
>>>>>>>>> +       LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
>>>>>>>>> +       LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
>>>>>>>>> +       LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
>>>>>>>>> +               thr, ntoolate);
>>>>>>>>> +       LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
>>>>>>>>> +       LOG_DBG("Thread %u: %u stale timeout(s) after
>>>>>>>>> odp_timer_free()\n",
>>>>>>>>> +               thr, nstale);
>>>>>>>>>
>>>>>>>>>          /* Delay some more to ensure timeouts for expired timers
>>>>>>>>> can
>>>>>>>>> be
>>>>>>>>>           * received */
>>>>>>>>> -       usleep(1000/*1ms*/);
>>>>>>>>> +       struct timespec ts;
>>>>>>>>> +       ts.tv_sec = 0;
>>>>>>>>> +       ts.tv_nsec = 1000000; /* 1ms */
>>>>>>>>> +       if (nanosleep(&ts, NULL) < 0)
>>>>>>>>> +               perror("nanosleep"), abort();
>>>>>>>>>          while (nstale != 0) {
>>>>>>>>>                  odp_buffer_t buf = odp_queue_deq(queue);
>>>>>>>>>                  if (buf != ODP_BUFFER_INVALID) {
>>>>>>>>> @@ -247,7 +262,7 @@ static void *worker_entrypoint(void *arg)
>>>>>>>>>          if (buf != ODP_BUFFER_INVALID)
>>>>>>>>>                  CU_FAIL("Unexpected buffer received");
>>>>>>>>>
>>>>>>>>> -       printf("Thread %u: exiting\n", thr);
>>>>>>>>> +       LOG_DBG("Thread %u: exiting\n", thr);
>>>>>>>>>          return NULL;
>>>>>>>>>   }
>>>>>>>>>
>>>>>>>>> @@ -256,9 +271,13 @@ static void test_odp_timer_all(void)
>>>>>>>>>   {
>>>>>>>>>          odp_buffer_pool_param_t params;
>>>>>>>>>          odp_timer_pool_param_t tparam;
>>>>>>>>> -       /* This is a stressfull test - need to reserve some cpu
>>>>>>>>> cycles
>>>>>>>>> -        * @TODO move to test/performance */
>>>>>>>>> -       int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
>>>>>>>>> +       /* Reserve at least one core for running other processes so
>>>>>>>>> the
>>>>>>>>> timer
>>>>>>>>> +        * test hopefully can run undisturbed and thus get better
>>>>>>>>> timing
>>>>>>>>> +        * results. */
>>>>>>>>> +       int num_workers = min(odp_sys_cpu_count() - 1,
>>>>>>>>> MAX_WORKERS);
>>>>>>>>> +       /* On a single-CPU machine run at least one thread */
>>>>>>>>> +       if (num_workers < 1)
>>>>>>>>> +               num_workers = 1;
>>>>>>>>>
>>>>>>>>>          /* Create timeout buffer pools */
>>>>>>>>>          params.buf_size  = 0;
>>>>>>>>> @@ -294,19 +313,11 @@ static void test_odp_timer_all(void)
>>>>>>>>>          CU_ASSERT(tpinfo.param.res_ns == RES);
>>>>>>>>>          CU_ASSERT(tpinfo.param.min_tmo == MIN);
>>>>>>>>>          CU_ASSERT(tpinfo.param.max_tmo == MAX);
>>>>>>>>> -       printf("Timer pool\n");
>>>>>>>>> -       printf("----------\n");
>>>>>>>>> -       printf("  name: %s\n", tpinfo.name);
>>>>>>>>> -       printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
>>>>>>>>> -              tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
>>>>>>>>> -       printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
>>>>>>>>> -       printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
>>>>>>>>> -       printf("\n");
>>>>>>>>> -
>>>>>>>>> -       printf("#timers..: %u\n", NTIMERS);
>>>>>>>>> -       printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>>>> -              odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>>>> -       printf("\n");
>>>>>>>>> +       CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
>>>>>>>>> +
>>>>>>>>> +       LOG_DBG("#timers..: %u\n", NTIMERS);
>>>>>>>>> +       LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
>>>>>>>>> +               odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
>>>>>>>>>
>>>>>>>>>          uint64_t tick;
>>>>>>>>>          for (tick = 0; tick < 1000000000000ULL; tick +=
>>>>>>>>> 1000000ULL)
>>>>>>>>> {
>>>>>>>>> @@ -319,6 +330,9 @@ static void test_odp_timer_all(void)
>>>>>>>>>          /* Initialize barrier used by worker threads for
>>>>>>>>> synchronization
>>>>>>>>> */
>>>>>>>>>          odp_barrier_init(&test_barrier, num_workers);
>>>>>>>>>
>>>>>>>>> +       /* Initialize the shared timeout counter */
>>>>>>>>> +       odp_atomic_init_u32(&ndelivtoolate, 0);
>>>>>>>>> +
>>>>>>>>>          /* Create and start worker threads */
>>>>>>>>>          pthrd_arg thrdarg;
>>>>>>>>>          thrdarg.testcase = 0;
>>>>>>>>> @@ -327,6 +341,8 @@ static void test_odp_timer_all(void)
>>>>>>>>>
>>>>>>>>>          /* Wait for worker threads to exit */
>>>>>>>>>          odp_cunit_thread_exit(&thrdarg);
>>>>>>>>> +       LOG_DBG("Number of timeouts delivered/received too late:
>>>>>>>>> %u\n",
>>>>>>>>> +               odp_atomic_load_u32(&ndelivtoolate));
>>>>>>>>>
>>>>>>>>>          /* Check some statistics after the test */
>>>>>>>>>          if (odp_timer_pool_info(tp, &tpinfo) != 0)
>>>>>>>>> --
>>>>>>>>> 1.9.1
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> _______________________________________________
>>>>>>>>> lng-odp mailing list
>>>>>>>>> lng-odp@lists.linaro.org
>>>>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> --
>>>>>>>> Mike Holmes
>>>>>>>> Linaro  Sr Technical Manager
>>>>>>>> LNG - ODP
>>>>>>>>
>>>>>>>> _______________________________________________
>>>>>>>> lng-odp mailing list
>>>>>>>> lng-odp@lists.linaro.org
>>>>>>>> http://lists.linaro.org/mailman/listinfo/lng-odp
>>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> Mike Holmes
>>>>>> Linaro  Sr Technical Manager
>>>>>> LNG - ODP
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> Mike Holmes
>>>>> Linaro  Sr Technical Manager
>>>>> LNG - ODP
>>>
>>>
>>>
>>>
>>> --
>>> Mike Holmes
>>> Linaro  Sr Technical Manager
>>> LNG - ODP
>>
>> _______________________________________________
>> lng-odp mailing list
>> lng-odp@lists.linaro.org
>> http://lists.linaro.org/mailman/listinfo/lng-odp
>
>
>
> _______________________________________________
> lng-odp mailing list
> lng-odp@lists.linaro.org
> http://lists.linaro.org/mailman/listinfo/lng-odp

Patch

diff --git a/test/validation/odp_timer.c b/test/validation/odp_timer.c
index 4c93f71..d893646 100644
--- a/test/validation/odp_timer.c
+++ b/test/validation/odp_timer.c
@@ -8,10 +8,13 @@ 
  * @file
  */
 
-#include <assert.h>
+/* For rand_r and nanosleep */
+#define _POSIX_C_SOURCE 200112L
+#include <time.h>
 #include <unistd.h>
 #include <odp.h>
 #include "odp_cunit_common.h"
+#include "test_debug.h"
 
 /** @private Timeout range in milliseconds (ms) */
 #define RANGE_MS 2000
@@ -28,6 +31,9 @@  static odp_buffer_pool_t tbp;
 /** @private Timer pool handle used by all threads */
 static odp_timer_pool_t tp;
 
+/** @private Count of timeouts delivered too late */
+static odp_atomic_u32_t ndelivtoolate;
+
 /** @private min() function */
 static int min(int a, int b)
 {
@@ -47,8 +53,7 @@  struct test_timer {
 /* @private Handle a received (timeout) buffer */
 static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t prev_tick)
 {
-	/* Use assert() for internal correctness checks of test program */
-	assert(buf != ODP_BUFFER_INVALID);
+	CU_ASSERT_FATAL(buf != ODP_BUFFER_INVALID); /* Internal error */
 	if (odp_buffer_type(buf) != ODP_BUFFER_TYPE_TIMEOUT) {
 		/* Not a timeout buffer */
 		CU_FAIL("Unexpected buffer type received");
@@ -65,38 +70,41 @@  static void handle_tmo(odp_buffer_t buf, bool stale, uint64_t prev_tick)
 	if (ttp == NULL)
 		CU_FAIL("odp_timeout_user_ptr() null user ptr");
 
-	if (ttp->buf2 != buf)
+	if (ttp != NULL && ttp->buf2 != buf)
 		CU_FAIL("odp_timeout_user_ptr() wrong user ptr");
-	if (ttp->tim != tim)
+	if (ttp != NULL && ttp->tim != tim)
 		CU_FAIL("odp_timeout_timer() wrong timer");
 	if (stale) {
 		if (odp_timeout_fresh(tmo))
 			CU_FAIL("Wrong status (fresh) for stale timeout");
 		/* Stale timeout => local timer must have invalid tick */
-		if (ttp->tick != TICK_INVALID)
+		if (ttp != NULL && ttp->tick != TICK_INVALID)
 			CU_FAIL("Stale timeout for active timer");
 	} else {
 		if (!odp_timeout_fresh(tmo))
 			CU_FAIL("Wrong status (stale) for fresh timeout");
 		/* Fresh timeout => local timer must have matching tick */
-		if (ttp->tick != tick) {
-			printf("Wrong tick: expected %"PRIu64" actual %"PRIu64"\n",
-			       ttp->tick, tick);
+		if (ttp != NULL && ttp->tick != tick) {
+			LOG_DBG("Wrong tick: expected %"PRIu64" actual %"PRIu64"\n",
+				ttp->tick, tick);
 			CU_FAIL("odp_timeout_tick() wrong tick");
 		}
 		/* Check that timeout was delivered 'timely' */
 		if (tick > odp_timer_current_tick(tp))
 			CU_FAIL("Timeout delivered early");
 		if (tick < prev_tick) {
-			printf("Too late tick: %"PRIu64" prev_tick %"PRIu64"\n",
-			       tick, prev_tick);
-			CU_FAIL("Timeout delivered late");
+			LOG_DBG("Too late tick: %"PRIu64" prev_tick %"PRIu64"\n",
+				tick, prev_tick);
+			/* We don't report late timeouts using CU_FAIL */
+			odp_atomic_inc_u32(&ndelivtoolate);
 		}
 	}
 
-	/* Use assert() for correctness check of test program itself */
-	assert(ttp->buf == ODP_BUFFER_INVALID);
-	ttp->buf = buf;
+	if (ttp != NULL) {
+		/* Internal error */
+		CU_ASSERT_FATAL(ttp->buf == ODP_BUFFER_INVALID);
+		ttp->buf = buf;
+	}
 }
 
 /* @private Worker thread entrypoint which performs timer alloc/set/cancel/free
@@ -203,8 +211,11 @@  static void *worker_entrypoint(void *arg)
 			/* Save expected expiration tick */
 			tt[i].tick = cur_tick + tck;
 		}
-		if (usleep(1000/*1ms*/) < 0)
-			perror("usleep"), abort();
+		struct timespec ts;
+		ts.tv_sec = 0;
+		ts.tv_nsec = 1000000; /* 1ms */
+		if (nanosleep(&ts, NULL) < 0)
+			perror("nanosleep"), abort();
 	}
 
 	/* Cancel and free all timers */
@@ -220,18 +231,22 @@  static void *worker_entrypoint(void *arg)
 			CU_FAIL("odp_timer_free");
 	}
 
-	printf("Thread %u: %u timers set\n", thr, nset);
-	printf("Thread %u: %u timers reset\n", thr, nreset);
-	printf("Thread %u: %u timers cancelled\n", thr, ncancel);
-	printf("Thread %u: %u timers reset/cancelled too late\n",
-	       thr, ntoolate);
-	printf("Thread %u: %u timeouts received\n", thr, nrcv);
-	printf("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
-	       thr, nstale);
+	LOG_DBG("Thread %u: %u timers set\n", thr, nset);
+	LOG_DBG("Thread %u: %u timers reset\n", thr, nreset);
+	LOG_DBG("Thread %u: %u timers cancelled\n", thr, ncancel);
+	LOG_DBG("Thread %u: %u timers reset/cancelled too late\n",
+		thr, ntoolate);
+	LOG_DBG("Thread %u: %u timeouts received\n", thr, nrcv);
+	LOG_DBG("Thread %u: %u stale timeout(s) after odp_timer_free()\n",
+		thr, nstale);
 
 	/* Delay some more to ensure timeouts for expired timers can be
 	 * received */
-	usleep(1000/*1ms*/);
+	struct timespec ts;
+	ts.tv_sec = 0;
+	ts.tv_nsec = 1000000; /* 1ms */
+	if (nanosleep(&ts, NULL) < 0)
+		perror("nanosleep"), abort();
 	while (nstale != 0) {
 		odp_buffer_t buf = odp_queue_deq(queue);
 		if (buf != ODP_BUFFER_INVALID) {
@@ -247,7 +262,7 @@  static void *worker_entrypoint(void *arg)
 	if (buf != ODP_BUFFER_INVALID)
 		CU_FAIL("Unexpected buffer received");
 
-	printf("Thread %u: exiting\n", thr);
+	LOG_DBG("Thread %u: exiting\n", thr);
 	return NULL;
 }
 
@@ -256,9 +271,13 @@  static void test_odp_timer_all(void)
 {
 	odp_buffer_pool_param_t params;
 	odp_timer_pool_param_t tparam;
-	/* This is a stressfull test - need to reserve some cpu cycles
-	 * @TODO move to test/performance */
-	int num_workers = min(odp_sys_cpu_count()-1, MAX_WORKERS);
+	/* Reserve at least one core for running other processes so the timer
+	 * test hopefully can run undisturbed and thus get better timing
+	 * results. */
+	int num_workers = min(odp_sys_cpu_count() - 1, MAX_WORKERS);
+	/* On a single-CPU machine run at least one thread */
+	if (num_workers < 1)
+		num_workers = 1;
 
 	/* Create timeout buffer pools */
 	params.buf_size  = 0;
@@ -294,19 +313,11 @@  static void test_odp_timer_all(void)
 	CU_ASSERT(tpinfo.param.res_ns == RES);
 	CU_ASSERT(tpinfo.param.min_tmo == MIN);
 	CU_ASSERT(tpinfo.param.max_tmo == MAX);
-	printf("Timer pool\n");
-	printf("----------\n");
-	printf("  name: %s\n", tpinfo.name);
-	printf("  resolution: %"PRIu64" ns (%"PRIu64" us)\n",
-	       tpinfo.param.res_ns, tpinfo.param.res_ns / 1000);
-	printf("  min tmo: %"PRIu64" ns\n", tpinfo.param.min_tmo);
-	printf("  max tmo: %"PRIu64" ns\n", tpinfo.param.max_tmo);
-	printf("\n");
-
-	printf("#timers..: %u\n", NTIMERS);
-	printf("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
-	       odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
-	printf("\n");
+	CU_ASSERT(strcmp(tpinfo.name, NAME) == 0);
+
+	LOG_DBG("#timers..: %u\n", NTIMERS);
+	LOG_DBG("Tmo range: %u ms (%"PRIu64" ticks)\n", RANGE_MS,
+		odp_timer_ns_to_tick(tp, 1000000ULL * RANGE_MS));
 
 	uint64_t tick;
 	for (tick = 0; tick < 1000000000000ULL; tick += 1000000ULL) {
@@ -319,6 +330,9 @@  static void test_odp_timer_all(void)
 	/* Initialize barrier used by worker threads for synchronization */
 	odp_barrier_init(&test_barrier, num_workers);
 
+	/* Initialize the shared timeout counter */
+	odp_atomic_init_u32(&ndelivtoolate, 0);
+
 	/* Create and start worker threads */
 	pthrd_arg thrdarg;
 	thrdarg.testcase = 0;
@@ -327,6 +341,8 @@  static void test_odp_timer_all(void)
 
 	/* Wait for worker threads to exit */
 	odp_cunit_thread_exit(&thrdarg);
+	LOG_DBG("Number of timeouts delivered/received too late: %u\n",
+		odp_atomic_load_u32(&ndelivtoolate));
 
 	/* Check some statistics after the test */
 	if (odp_timer_pool_info(tp, &tpinfo) != 0)