Search code examples
ccontikicooja

Energest CPU readings in Contiki Cooja simulation of Sky mote are decreasing

My Energest energy estimations are not making sense in a Cooja simulation of a Sky mote. I want to read out CPU, TX and RX values before and after encryption and transmission of data from one mote to another. The readings of total CPU are first increasing but after a few rounds suddenly decreasing again. My understanding is that they don't reset but displaying the total count of clicks. Therefore I am subtracting old values from current values to display consumption of each period.

energest_init();


printf("Ticks per second: %u\n", RTIMER_SECOND);

  while(1) {


PROCESS_WAIT_EVENT_UNTIL(etimer_expired(&periodic_timer));
etimer_reset(&periodic_timer);
etimer_set(&send_timer, SEND_TIME);

PROCESS_WAIT_EVENT_UNTIL(etimer_expired(&send_timer));
addr = servreg_hack_lookup(SERVICE_ID);
if(addr != NULL) {

  powertrace_getold(); 
  //here happens what I want to track
  powertrace_print("");
} else {
  printf("Service %d not found\n", SERVICE_ID);
}
}

here the Energest functions I call

void powertrace_getold(void){

  energest_flush();
  last_cpu = energest_type_time(ENERGEST_TYPE_CPU);
  last_lpm = energest_type_time(ENERGEST_TYPE_LPM);
  last_transmit = energest_type_time(ENERGEST_TYPE_TRANSMIT);
  last_listen = energest_type_time(ENERGEST_TYPE_LISTEN);
}



/*---------------------------------------------------------------------------*/
void
powertrace_print(char *str)

{
  uint32_t cpu, lpm, transmit, listen;
  uint32_t all_cpu, all_lpm, all_transmit, all_listen;

  static uint32_t seqno;

  energest_flush();
  seqno++;  
  all_cpu = energest_type_time(ENERGEST_TYPE_CPU);
  all_lpm = energest_type_time(ENERGEST_TYPE_LPM);
  all_transmit = energest_type_time(ENERGEST_TYPE_TRANSMIT);
  all_listen = energest_type_time(ENERGEST_TYPE_LISTEN);

  cpu = all_cpu - last_cpu;
  lpm = all_lpm - last_lpm;
  transmit = all_transmit - last_transmit;
  listen = all_listen - last_listen;

printf("SQ:%d AllCPU:%lu AllLPM:%lu AllTX:%lu AllLST:%lu\n",seqno, all_cpu,all_lpm,all_transmit,all_listen);
printf("SQ:%d    CPU:%lu LPM:%lu TX:%lu LST:%lu\n",seqno,cpu,lpm,transmit,listen);

}

Here some output:

SQ:1 AllCPU:1186791424 AllLPM:756219905 AllTX:1756561462 AllLST:1931870208
SQ:1    CPU:93716480 LPM:93716480 TX:93650944 LST:93650944
SQ:2 AllCPU:3010854912 AllLPM:3091398657 AllTX:2625110086 AllLST:2710700032
SQ:2    CPU:93716480 LPM:93716480 TX:93782016 LST:93716480
SQ:3 AllCPU:4026073088 AllLPM:2875260929 AllTX:2958426201 AllLST:3292790784
SQ:3    CPU:97386496 LPM:97320960 TX:97320960 LST:1703936
SQ:4 AllCPU:2539323392 AllLPM:2459107330 AllTX:3841982587 AllLST:123666432
SQ:4    CPU:97320960 LPM:97320960 TX:97320960 LST:1703936
SQ:5 AllCPU:194379776 AllLPM:3890544643 AllTX:4187422878 AllLST:1273561088
SQ:5    CPU:93782016 LPM:93782016 TX:93782016 LST:93716480
SQ:6 AllCPU:1199505408 AllLPM:2522808323 AllTX:183107761 AllLST:1925709825
SQ:6    CPU:93978624 LPM:93913088 TX:93913088 LST:93978624

As you can see the values don't add up. What am I missing? ENERGEST_ON/OFF does not help change anything either.

Solution

  • You define all_cpu, all_lpm, all_transmit, and all_listen as 32-bit unsigned integers. A 32-bit unsigned integer can only hold values up to 232-1. If you look at the sequence of all CPU ticks (1186791424, 3010854912, 4026073088, ...) you can see that 4026073088 is pretty close to 232-1 (4294967295), so it no surprise that the next printed value (2539323392) is smaller than that - the variable has overflown.

    To solve that you can either:

    1. Store the ticks in uint64_t instead of uint32_t.
    2. Reduce the number of rtimer ticks per second - but on Sky it is hardware dependent, so doing that will be nontrivial.
    3. Detect the overflow and account for them later: it is, for example notice each time the counter has decreased and keep the overflow counter in a separate variable. It's likely you can do that in the post-processing stage when you analyze the logs - you just need to make sure the counters are printed frequently enough so that there can be at most one overflow between each call to powertrace_print().