Import PSI KPI profiler code
[gstreamer-omap:libdce.git] / ducati / ti / dce / baseimage / profile.c
1 /* ====================================================================
2  *   Copyright (C) 2010 Texas Instruments Incorporated
3  *
4  *   All rights reserved. Property of Texas Instruments Incorporated.
5  *   Restricted rights to use, duplicate or disclose this code are
6  *   granted through contract.
7  *
8  *   The program may not be used without the written permission
9  *   of Texas Instruments Incorporated or against the terms and conditions
10  *   stipulated in the agreement under which this program has been
11  *   supplied.
12  * ==================================================================== */
13 /*
14 *   @file  profile.c
15 *   This file contains kpi psi instrumentation code for cpu load as well
16 *   as tracing codec + OMX events
17 *
18 *   @path \WTSD_DucatiMMSW\platform\utils\
19 *
20 *  @rev 1.0
21 */
22
23 /* PSI_KPI profiler */
24 #include "profile.h"
25
26 #include "timm_osal_trace.h"
27 #include "timm_osal_mutex.h"
28
29 #include <string.h>
30 #include <xdc/std.h>
31 #include <xdc/runtime/Error.h>
32
33 #include <ti/sysbios/BIOS.h>
34 #include <ti/sysbios/knl/Task.h>
35 #include <ti/sysbios/hal/Hwi.h>
36 #include <ti/sysbios/knl/Swi.h>
37 #include <xdc/runtime/Types.h>
38 #include <xdc/runtime/Timestamp.h>
39 #ifdef  BUILD_FOR_SMP
40 #include <ti/sysbios/hal/Core.h>
41 #endif//BUILD_FOR_SMP
42 #include <ti/sysbios/family/arm/ducati/TimestampProvider.h>
43 #include <ti/pm/IpcPower.h>
44 #include <WTSD_DucatiMMSW/framework/tools_library/inc/tools_time.h>
45
46
47 /* private function prototypes */
48 void kpi_IVA_profiler_init  (void);
49 void kpi_CPU_profiler_init  (void);
50 void kpi_IVA_profiler_print (void);
51 void kpi_CPU_profiler_print (void);
52 void psi_kpi_task_test(Task_Handle prev, Task_Handle next);
53
54
55 /***************************************************************
56  * psi_tsk_info
57  * -------------------------------------------------------------
58  * Structure maintaining task data for Duacti CPU load
59  *
60  ***************************************************************/
61 #define KPI_CONTEXT_TASK  0
62 #define KPI_CONTEXT_SWI   1
63 #define KPI_CONTEXT_HWI   2
64
65 typedef struct {
66   void          *handle;      /* Pointer to task handle, used to identify task */
67   char           name[50];    /* Task name */
68   unsigned long  total_time;  /* Total time spent in the task context */
69   unsigned long  nb_switch;   /* Number of times the context get activated */
70 } psi_context_info;
71
72
73 /***************************************************************
74  * psi_bios_kpi
75  * -------------------------------------------------------------
76  * Structure maintaining data for Ducati CPU load
77  *
78  ***************************************************************/
79 #define CTX_DIRECT_NUM   256
80 #define KPI_MAX_NB_TASKS 64
81 #define KPI_MAX_NB_SWI   16
82 #define KPI_MAX_NB_HWI   16
83 #define MAX_NB_IT 32
84
85 typedef struct {
86   unsigned long    prev_t32;                      /* Store T32K value of previous task switch */
87   unsigned long    total_time;                    /* Total processing time */
88   unsigned long    kpi_time;                      /* Total instrumentation processing time */
89   unsigned long    kpi_count;                     /* Number of time instrumentation run */
90   unsigned long    nb_switch;                     /* Number of context switches */
91
92   psi_context_info tasks[KPI_MAX_NB_TASKS];       /* Tasks info DB */
93   unsigned long    nb_tasks;                      /* Number of tasks in task info */
94   psi_context_info hwi[KPI_MAX_NB_SWI];           /* HWI info DB */
95   unsigned long    nb_hwi;                        /* Number of HWI in HWI info */
96   psi_context_info swi[KPI_MAX_NB_HWI];           /* SWI info DB */
97   unsigned long    nb_swi;                        /* Number of SWI in SWI info */
98
99   psi_context_info* context_cache[CTX_DIRECT_NUM];/* pointers to tasks info DB */
100
101   void*            context_stack[MAX_NB_IT];      /* to keep handles because of swi hwi */
102   void**           pt_context_stack;              /* stack pointer */
103
104   unsigned long   *ptr_idle_total;                /* to access to idle task total directly */
105   unsigned long    idle_prev;                     /* total ticks of idle task previously */
106   unsigned long    idle_time_prev;                /* time of idle_prev measure */
107
108   unsigned long    trace_time;                    /* time spent tracing */
109 } psi_bios_kpi;
110
111
112 /***************************************************************
113  * ivahd_kpi
114  * -------------------------------------------------------------
115  * Structure maintaining data for IVA-HD load and fps
116  *
117  ***************************************************************/
118 typedef struct {
119   unsigned long ivahd_t_tot;         /* IVA-HD tot processing time per frame */
120   unsigned long ivahd_t_max;         /* IVA-HD max processing time per frame */
121   unsigned long ivahd_t_min;         /* IVA-HD min processing time per frame */
122   unsigned long ivahd_t_max_frame;
123   unsigned long ivahd_t_min_frame;
124
125   unsigned long omx_nb_frames;       /* Number of frames      */
126
127   unsigned long before_time;         /* T32K before codec execution */
128   unsigned long after_time;          /* T32K after codec execution */
129
130   unsigned long t32k_start;          /* T32K value at the beginning of video decode */
131   unsigned long t32k_end;            /* T32K value at the end of video decode */
132 } psi_iva_kpi;
133
134
135 /***************************************************************
136  * Globals
137  ***************************************************************/
138 unsigned long kpi_control = 0;       /* instrumentation control (set with omapconf) */
139 unsigned long kpi_status  = 0;       /* instrumentation status variables */
140
141 psi_iva_kpi   iva_kpi;               /* IVA data base */
142 psi_bios_kpi  bios_kpi[2];           /* CPU data base (2 cores) */
143
144
145 /***************************************************************
146  * Functions
147  ***************************************************************/
148
149 #ifndef BUILD_FOR_SMP
150 /***************************************************************
151  * Core_getCoreId
152  * -------------------------------------------------------------
153  * Temporary function to remove with SMP BIOS
154  *
155  * @params: none
156  *
157  * @return: 1 to force CoreId to 1
158  *
159  ***************************************************************/
160 unsigned long Core_getCoreId( void )
161 {
162   return 1;
163 }
164 #endif//BUILD_FOR_SMP
165
166 /***************************************************************
167  * get_32k
168  * -------------------------------------------------------------
169  * Function used to get 32k timer value
170  *
171  * @params: none
172  *
173  * @return: T32k value
174  *
175  ***************************************************************/
176 unsigned long get_32k(void)
177 {
178   return ( Tools_Time_get32k() );
179 }
180
181 /***************************************************************
182  * get_time
183  * -------------------------------------------------------------
184  * Left here for test
185  *
186  * @params: none
187  *
188  * @return: CTM timer value / 4096 (~100KHz)
189  *          or 32K value (slower to read)
190  *
191  ***************************************************************/
192 inline unsigned long get_time( void )
193 #ifdef USE_CTM_TIMER
194 {
195   Types_Timestamp64 tTicks;
196
197   TimestampProvider_get64( &tTicks );
198   return ( (unsigned long) (tTicks.lo >> 12) + (unsigned long) (tTicks.hi << 20) );
199 }
200 #else/*USE_CTM_TIMER*/
201 {
202   return get_32k();
203 }
204 #endif/*USE_CTM_TIMER*/
205
206 /***************************************************************
207  * get_time_core
208  * -------------------------------------------------------------
209  * Left here for test
210  *
211  * @params: int core
212  *
213  * @return: CTM timer value / 4096 (~100KHz)
214  *          or 32K value (slower to read)
215  *
216  * This function is equivalent to get_time().
217  * it can be called when interrupts have been masked
218  * and when current core Id is known already (therefore faster)
219  ***************************************************************/
220 inline unsigned long get_time_core( int core )
221 #ifdef USE_CTM_TIMER
222 {
223   Types_Timestamp64 tTicks;
224
225     tTicks.hi = *(volatile unsigned long *) (0x40000400 + 0x180 + 0xc + (core<<3));
226     tTicks.lo = *(volatile unsigned long *) (0x40000400 + 0x180 + 0x8 + (core<<3));
227
228   return ( (unsigned long) (tTicks.lo >> 12) + (unsigned long) (tTicks.hi << 20) );
229 }
230 #else /*USE_CTM_TIMER*/
231 {
232   return get_32k();
233 }
234 #endif/*USE_CTM_TIMER*/
235
236 /***************************************************************
237  * set_WKUPAON
238  * -------------------------------------------------------------
239  * Function used to get fast access to the 32k timer value
240  *
241  * @params: int force_restore (1 or 0)
242  *
243  * @return: none
244  *
245  * This function prevents sleep mode to the L4 WKUPAON_CM
246  * register, to avoid large stalls when reading the 32k timer
247  ***************************************************************/
248 void set_WKUPAON(int force_restore)
249 {
250 #ifdef  BUILD_FOR_OMAP5
251   static unsigned long clktrctrl_01=0;
252   unsigned long reg = *((volatile OMX_U32 *)0xAAE07800);
253
254   /* Force nosleep mode or restore original configuration */
255   if( force_restore == 1 ) {
256     clktrctrl_01 = reg & 0x3;         /* save clktrctrl */
257     reg &= 0xfffffffc;
258     //reg |= 0x2;                     /* force SW_WAKEUP */
259     reg |= 0;                         /* force NO_SLEEP */
260   } else {
261     reg &= 0xfffffffc;
262     reg |= clktrctrl_01;              /* restore bits 01 */
263     clktrctrl_01 = 0;                 /* restore done */
264   }
265   *(OMX_U32 *)0xAAE07800 = reg;
266 #endif/*BUILD_FOR_OMAP5*/
267 }
268
269
270 /***************************************************************
271  * PSI_TracePrintf
272  * -------------------------------------------------------------
273  * Function used to get 32k timer value
274  *
275  * @params: TIMM_OSAL_TRACEGRP eTraceGrp, TIMM_OSAL_CHAR *pcFormat, ...
276  *
277  * @return: none
278  *
279  ***************************************************************/
280 void PSI_TracePrintf(TIMM_OSAL_TRACEGRP eTraceGrp, TIMM_OSAL_CHAR *pcFormat, ...)
281 {
282 //  static TIMM_OSAL_PTR MyMutex = NULL;
283   unsigned long tstart = get_time();
284   unsigned long key = Task_disable();
285   unsigned long CoreId = Core_getCoreId();
286
287 //  if(!MyMutex) TIMM_OSAL_MutexCreate( &MyMutex );
288 //  TIMM_OSAL_MutexObtain(MyMutex, TIMM_OSAL_SUSPEND);
289
290   va_list varArgs;
291   va_start(varArgs, pcFormat);
292   System_vprintf(pcFormat, varArgs);
293 // TIMM_OSAL_TracePrintfV(eTraceGrp, pcFormat, varArgs);
294   va_end(varArgs);
295
296 //  TIMM_OSAL_MutexRelease(MyMutex);
297   Task_restore(key);
298
299   /* count overhead due to tracing when running (phase 1)*/
300   if( kpi_status & KPI_INST_RUN ) bios_kpi[CoreId].trace_time += get_time()-tstart;
301
302 }
303
304
305 /***************************************************************
306  * kpi_instInit
307  * -------------------------------------------------------------
308  * Function used to do the aquisition of the instrumentation
309  * setting. Then initialising the DBs and variables
310  *
311  * @params: none
312  *
313  * @return: none
314  *
315  ***************************************************************/
316 void kpi_instInit( void )
317 {
318   /* don't change setup when already active */
319   if( kpi_status & KPI_INST_RUN )
320     return;
321
322   /* read control from the memory */
323
324   /* Note:
325    * kpi_control |= KPI_END_SUMMARY;     bit0 : Activate the IVA and CPU load measure and print summary
326    * kpi_control |= KPI_IVA_DETAILS;     bit1 : Activate the IVA trace
327    * kpi_control |= KPI_OMX_DETAILS;     bit2 : Activate the OMX trace
328    * kpi_control |= KPI_CPU_DETAILS;     bit3 : Activate the CPU Idle trace
329    */
330
331   /* reset kpi_status */
332   kpi_status = 0;
333
334   /* nothing to do if no instrumentation required */
335   if( !kpi_control )
336     return;
337
338   /* force clktrctrl to no sleep mode (fast 32k access) */
339   //set_WKUPAON( 1 );
340 #ifdef  USE_CTM_TIMER
341   IpcPower_wakeLock();
342 #endif/*USE_CTM_TIMER*/
343
344   /* IVA load setup */
345   if( kpi_control & (KPI_END_SUMMARY | KPI_IVA_DETAILS) )
346   {
347     /* Initialize the IVA data base */
348     kpi_IVA_profiler_init();
349     kpi_status |= KPI_IVA_LOAD;
350     if ( kpi_control & KPI_IVA_DETAILS )
351       kpi_status |= KPI_IVA_TRACE;
352   }
353
354   /* CPU load setup */
355   if( kpi_control & (KPI_END_SUMMARY | KPI_CPU_DETAILS) )
356   {
357     /* Initialize the CPU data base */
358     kpi_CPU_profiler_init();
359     kpi_status |= KPI_CPU_LOAD;
360     if ( kpi_control & KPI_CPU_DETAILS )
361       kpi_status |= KPI_CPU_TRACE;
362   }
363
364   /* OMX trace setup */
365   if( kpi_control & KPI_OMX_DETAILS )
366   {
367     kpi_status |= KPI_OMX_TRACE;
368   }
369
370   /* Mark as running */
371   kpi_status |= KPI_INST_RUN;
372
373 }
374
375 /***************************************************************
376  * kpi_instDeinit
377  * -------------------------------------------------------------
378  * Function used stop the instrumentation
379  * Then initialising the summary if required
380  *
381  * @params: none
382  *
383  * @return: none
384  *
385  ***************************************************************/
386 void kpi_instDeinit( void )
387 {
388   unsigned long cpu_summary=0;
389   unsigned long iva_summary=0;
390
391   /* noting to do when not running */
392   if( !(kpi_status & KPI_INST_RUN) )
393     return;
394
395   if( kpi_control & KPI_END_SUMMARY )
396   {
397     cpu_summary = kpi_status & KPI_CPU_LOAD;
398     iva_summary = kpi_status & KPI_IVA_LOAD;
399   }
400
401   /* now stop everything since measure is completed */
402   kpi_status = 0;
403
404   /* Print the summarys */
405   PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "\n<KPI> Profiler Deinit %-8lu\n", get_32k() );
406   if (iva_summary) kpi_IVA_profiler_print();
407   if (cpu_summary) kpi_CPU_profiler_print();
408
409   /* restore clktrctrl register */
410   //set_WKUPAON( 0 );
411 #ifdef  USE_CTM_TIMER
412   IpcPower_wakeUnlock();
413 #endif/*USE_CTM_TIMER*/
414
415 }
416
417
418 /***************************/
419 /* IVA fps and IVA-HD load */
420 /***************************/
421
422 #ifdef  CPU_LOAD_DETAILS
423 /***************************************************************
424  * psi_cpu_load_details
425  * -------------------------------------------------------------
426  * Function to be called once a frame
427  *
428  * @params: none
429  *
430  * @return: none
431  *
432  ***************************************************************/
433 void psi_cpu_load_details(void)
434 {
435   unsigned long time_curr = get_time();
436   unsigned long CoreId, time_delta, idle_delta, idle;
437   psi_bios_kpi *core_kpi;
438   char trace[2][50];
439
440   /* calculate delta_time and delta_idle */
441   for( CoreId = 0; CoreId < 2; CoreId++)
442   {
443     core_kpi = &bios_kpi[CoreId];
444     sprintf( trace[CoreId], "");
445     idle_delta= *(core_kpi->ptr_idle_total) - core_kpi->idle_prev;
446     time_delta = time_curr - core_kpi->idle_time_prev;
447     /* calculate idle value only if it was updated (idle task switch happend at least once!) */
448     if( idle_delta ) {
449       core_kpi->idle_time_prev = time_curr;
450       core_kpi->idle_prev = *(core_kpi->ptr_idle_total);
451       if( time_delta ) {
452         /* calculate Idle %time */
453         idle = ((idle_delta * 100) + time_delta/2) / time_delta;
454         sprintf( trace[CoreId], "Idle.%lu : %lu%%", CoreId, idle );
455       }
456     }
457   }
458
459   PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "%s   %s\n", trace[0], trace[1]);
460 }
461 #endif//CPU_LOAD_DETAILS
462
463
464 /***************************************************************
465  * kpi_IVA_profiler_init
466  * -------------------------------------------------------------
467  * Function to be called at start of processing.
468  *
469  * @params: none
470  *
471  * @return: none
472  *
473  ***************************************************************/
474 void kpi_IVA_profiler_init(void)
475 {
476
477   PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "<KPI> IVA Profiler Init %-8lu\n", get_32k() );
478
479   iva_kpi.ivahd_t_tot       = 0;         /* IVA-HD tot processing time per frame */
480   iva_kpi.ivahd_t_max       = 0;         /* IVA-HD max processing time per frame */
481   iva_kpi.ivahd_t_min       =~0;         /* IVA-HD min processing time per frame */
482   iva_kpi.ivahd_t_max_frame = 0;
483   iva_kpi.ivahd_t_min_frame = 0;
484
485   iva_kpi.omx_nb_frames     = 0;         /* Number of frames      */
486
487   iva_kpi.before_time       = 0;
488   iva_kpi.after_time        = 0;
489
490   iva_kpi.t32k_start        = 0;
491   iva_kpi.t32k_end          = 0;
492
493 }
494
495 /***************************************************************
496  * kpi_before_codec
497  * -------------------------------------------------------------
498  * Function to be called before codec execution.
499  *
500  * @params: none
501  *
502  * @return: none
503  *
504  ***************************************************************/
505 void kpi_before_codec(void)
506 {
507   unsigned long start, prev, delta;
508
509 #ifndef OMX_ENABLE_DUCATI_LOAD
510   /* Started 1st time */
511   if( !(kpi_status & KPI_INST_RUN) )
512     kpi_instInit();
513 #endif//OMX_ENABLE_DUCATI_LOAD
514
515   if( kpi_status & KPI_IVA_LOAD )
516   {
517     /* read the 32k timer */
518     start = get_32k();
519
520     prev = iva_kpi.before_time;
521     iva_kpi.before_time = start;
522
523     /* record very 1st time codec is used */
524     if ( !iva_kpi.t32k_start ) iva_kpi.t32k_start = iva_kpi.before_time;
525
526     /* calculate delta frame time in ticks */
527     delta = start - prev;
528     if(!iva_kpi.omx_nb_frames)  delta = 0;
529
530 #ifdef  IVA_DETAILS
531     if( kpi_status & KPI_IVA_TRACE )
532     {
533       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "BEG %-7s %-4u %-8lu %d\n",
534        "IVA", iva_kpi.omx_nb_frames + 1, start, (delta * 100000) / 32768);
535     }
536 #endif/*IVA_DETAILS*/
537
538   }
539
540 #ifdef  CPU_LOAD_DETAILS
541   if( kpi_status & KPI_CPU_TRACE )
542   {
543     kpi_status |= KPI_IVA_USED; /* mark IVA actually used */
544     psi_cpu_load_details();
545   }
546 #endif//CPU_LOAD_DETAILS
547
548 }
549
550 /***************************************************************
551  * kpi_after_codec
552  * -------------------------------------------------------------
553  * Function to be called at the end of processing.
554  *
555  * @params: none
556  *
557  * @return: none
558  *
559  ***************************************************************/
560 void kpi_after_codec(void)
561 {
562   unsigned long processing_time;
563
564   if( kpi_status & KPI_IVA_LOAD )
565   {
566     /* Read 32k timer */
567     iva_kpi.after_time = get_32k();
568     iva_kpi.t32k_end   = iva_kpi.after_time;
569
570     /* Process IVA-HD working time */
571     processing_time = iva_kpi.after_time - iva_kpi.before_time;
572
573 #ifdef  IVA_DETAILS
574     if( kpi_status & KPI_IVA_TRACE )
575     {
576       /* transform 32KHz ticks into ms */
577       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "END %-7s %-4u %-8lu %d\n",
578           "IVA", iva_kpi.omx_nb_frames + 1, iva_kpi.after_time, (processing_time * 100000) / 32768);
579     }
580 #endif/*IVA_DETAILS*/
581
582     /* Total for Average */
583     iva_kpi.ivahd_t_tot = (iva_kpi.ivahd_t_tot + processing_time);
584
585     /* Max */
586     if (processing_time > iva_kpi.ivahd_t_max)
587     {
588       iva_kpi.ivahd_t_max       = processing_time;
589       iva_kpi.ivahd_t_max_frame = iva_kpi.omx_nb_frames + 1;
590     }
591
592     /* Min */
593     if (processing_time < iva_kpi.ivahd_t_min)
594     {
595       iva_kpi.ivahd_t_min       = processing_time;
596       iva_kpi.ivahd_t_min_frame = iva_kpi.omx_nb_frames + 1;
597     }
598
599     iva_kpi.omx_nb_frames++;
600
601   }
602
603 }
604
605 /***************************************************************
606  * kpi_IVA_profiler_print
607  * -------------------------------------------------------------
608  * Function to be called after codec execution.
609  *
610  * It is printing all results. syslink_trace_daemon must be enabled
611  *
612  * @params: none
613  *
614  * @return: none
615  *
616  ***************************************************************/
617 void kpi_IVA_profiler_print(void)
618 {
619   unsigned long total_time, fps_x100, fps, frtick_x10, Ivatick_x10, Iva_pct;
620
621   /* Calculate the total time */
622   total_time = iva_kpi.t32k_end - iva_kpi.t32k_start;
623
624   if (total_time) {
625
626      /* Calculate the frame period and the framerate */
627      if( iva_kpi.omx_nb_frames ) {
628         frtick_x10 = total_time*10 / iva_kpi.omx_nb_frames;
629         fps_x100 = 32768 * 1000 / frtick_x10;
630         fps = fps_x100 / 100;
631      }
632
633      /* Calculate the IVA load */
634      if( iva_kpi.omx_nb_frames ) {
635         Ivatick_x10 = (iva_kpi.ivahd_t_tot*10 / iva_kpi.omx_nb_frames);
636         Iva_pct = Ivatick_x10 * 100 / frtick_x10;
637      }
638
639      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
640      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "Ducati stats:\n");
641      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "-------------\n");
642      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "      IVA  1st beg: %lu\n", iva_kpi.t32k_start);
643      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "      IVA last end: %lu\n", iva_kpi.t32k_end);
644      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "        Total time: %lu\n", total_time);
645      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, " Number of samples: %lu\n", iva_kpi.omx_nb_frames);
646      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, " Period of samples: %lu\n", frtick_x10/10);
647      PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "               fps: %2d.%02d\n", fps, fps_x100-(fps*100) );
648
649      /* stat existing only if frames were processed */
650      if( iva_kpi.omx_nb_frames ) {
651        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "\n");
652        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
653        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "IVA-HD processing time:\n");
654        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "-----------------------\n");
655        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "       IVA average: %d\n", iva_kpi.ivahd_t_tot / iva_kpi.omx_nb_frames);
656        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "           IVA max: %d frame: %d\n", iva_kpi.ivahd_t_max, iva_kpi.ivahd_t_max_frame);
657        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "           IVA min: %d frame: %d\n", iva_kpi.ivahd_t_min, iva_kpi.ivahd_t_min_frame);
658        PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "           IVA use: %d %%\n\n", Iva_pct);
659     }
660   }
661
662 }
663
664
665 /***************************/
666 /* OMX FillThisBuffer      */
667 /*     EmptyThisBuffer     */
668 /* end FillBufferDone      */
669 /*     EmptyBufferDone     */
670 /***************************/
671
672 /***************************************************************
673  * psi_omx_component
674  * -------------------------------------------------------------
675  * Structure maintenaing data for Ducati OMX traces
676  *
677  ***************************************************************/
678 typedef struct {
679         OMX_HANDLETYPE hComponent;
680         OMX_U32 count_ftb;
681         OMX_U32 count_fbd;
682         OMX_U32 count_etb;
683         OMX_U32 count_ebd;
684         char    name[50];
685 } psi_omx_component;
686
687 /* we trace up to MAX_OMX_COMP components */
688 #define MAX_OMX_COMP 8
689
690 /***************************************************************
691  * kpi_omx_monitor
692  * -------------------------------------------------------------
693  * Contains up to 8 components data
694  *
695  ***************************************************************/
696 psi_omx_component kpi_omx_monitor[MAX_OMX_COMP]; /* we trace up to MAX_OMX_COMP components */
697 OMX_U32 kpi_omx_monitor_cnt=0;                   /* no component yet */
698
699
700 /***************************************************************
701  * kpi_omx_comp_init
702  * -------------------------------------------------------------
703  * setup monitor data
704  *
705  * @params: OMX_HANDLETYPE hComponent
706  *
707  * @return: none
708  *
709  ***************************************************************/
710 void kpi_omx_comp_init( OMX_HANDLETYPE hComponent )
711 {
712
713   OMX_VERSIONTYPE nVersionComp;
714   OMX_VERSIONTYPE nVersionSpec;
715   OMX_UUIDTYPE    compUUID;
716   char compName[OMX_MAX_STRINGNAME_SIZE];
717   char* p;
718   OMX_U32 omx_cnt;
719
720 #ifdef  OMX_ENABLE_DUCATI_LOAD
721   /* Started 1st time */
722   if( !(kpi_status & KPI_INST_RUN) )
723     kpi_instInit();
724 #endif//OMX_ENABLE_DUCATI_LOAD
725
726   if( kpi_status & KPI_OMX_TRACE )
727   {
728
729     /* First init: clear kpi_omx_monitor components */
730     if( kpi_omx_monitor_cnt == 0) {
731       for (omx_cnt=0; omx_cnt < MAX_OMX_COMP; omx_cnt++) {
732          /*clear handler registery */
733          kpi_omx_monitor[omx_cnt].hComponent = 0;
734       }
735     }
736
737     /* identify the 1st component free in the table (maybe one was removed previously) */
738     for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
739        if( kpi_omx_monitor[omx_cnt].hComponent == 0 ) break;
740     }
741
742     if( omx_cnt >= MAX_OMX_COMP ) return;
743
744     /* current comp num and update */
745     kpi_omx_monitor_cnt++;
746
747     /* register the component handle */
748     kpi_omx_monitor[omx_cnt].hComponent = hComponent;
749
750     /* reset event counts */
751     kpi_omx_monitor[omx_cnt].count_ftb = 0;
752     kpi_omx_monitor[omx_cnt].count_fbd = 0;
753     kpi_omx_monitor[omx_cnt].count_etb = 0;
754     kpi_omx_monitor[omx_cnt].count_ebd = 0;
755
756     /* register the component name */
757     ((OMX_COMPONENTTYPE*) hComponent)->GetComponentVersion(hComponent, compName, &nVersionComp, &nVersionSpec, &compUUID);
758     /* get the end of the string compName... */
759     p = compName + strlen( compName ) - 1;
760     if (strlen( compName ) >= 40) p = compName + 40 - 1;          // Fix for very long names
761     while( (*p != '.' ) && (p != compName) ) p--;                 // Find last "."
762     strncpy( kpi_omx_monitor[omx_cnt].name, p + 1, 6 );           // keep 6 last chars after "."
763     *(kpi_omx_monitor[omx_cnt].name + 6) = '\0';                  // complete the chain of char
764     sprintf(kpi_omx_monitor[omx_cnt].name, "%s%d", kpi_omx_monitor[omx_cnt].name, omx_cnt ); // Add index to the name
765     /* trace component init */
766     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "<KPI> OMX %-8s Init %-8lu \n", kpi_omx_monitor[omx_cnt].name, get_32k() );
767
768   }
769
770 }
771
772 /***************************************************************
773  * kpi_omx_comp_deinit
774  * -------------------------------------------------------------
775  * deinit monitor data
776  *
777  * @params: OMX_HANDLETYPE hComponent
778  *
779  * @return: none
780  *
781  ***************************************************************/
782 void kpi_omx_comp_deinit( OMX_HANDLETYPE hComponent )
783 {
784
785   OMX_U32 omx_cnt;
786
787   if( kpi_omx_monitor_cnt > 0)
788   {
789     /* identify the component from the registery */
790     for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
791       if( kpi_omx_monitor[omx_cnt].hComponent == hComponent ) break;
792     }
793
794     /* trace component deinit */
795     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "<KPI> OMX %-7s Deinit %-8lu\n", kpi_omx_monitor[omx_cnt].name, get_32k() );
796
797     /* unregister the component */
798     kpi_omx_monitor[omx_cnt].hComponent = 0;
799
800     kpi_omx_monitor_cnt--;
801   }
802
803   /* stop the instrumentation */
804   if( kpi_omx_monitor_cnt == 0) kpi_instDeinit();
805
806 }
807
808 /***************************************************************
809  * kpi_omx_comp_FTB
810  * -------------------------------------------------------------
811  * Trace FillThisBuffer() event
812  *
813  * @params: OMX_HANDLETYPE hComponent
814  *          OMX_BUFFERHEADERTYPE* pBuffer
815  *
816  * @return: none
817  *
818  ***************************************************************/
819 void kpi_omx_comp_FTB( OMX_HANDLETYPE hComponent, OMX_BUFFERHEADERTYPE* pBuffer )
820 {
821 #ifdef  OMX_DETAILS
822   OMX_U32 omx_cnt;
823
824   if( kpi_omx_monitor_cnt == 0) return;
825
826   /* identify the component from the registery */
827   for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
828     if( kpi_omx_monitor[omx_cnt].hComponent == hComponent ) break;
829   }
830
831   /* Update counts and trace the event */
832   if( omx_cnt < MAX_OMX_COMP ) {
833     /* trace the event */
834     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "FTB %-7s %-4u %-8lu x%-8x\n",
835 #ifdef PHYSICAL_BUFFER
836     kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_ftb, get_32k(), pBuffer->pBuffer );
837 #else
838     kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_ftb, get_32k(), pBuffer );
839 #endif
840   }
841 #endif//OMX_DETAILS
842
843 }
844
845 /***************************************************************
846  * kpi_omx_comp_FBD
847  * -------------------------------------------------------------
848  * Trace FillBufferDone() event
849  *
850  * @params: OMX_HANDLETYPE hComponent
851  *          OMX_BUFFERHEADERTYPE* pBuffer
852  *
853  * @return: none
854  *
855  ***************************************************************/
856 void kpi_omx_comp_FBD( OMX_HANDLETYPE hComponent, OMX_BUFFERHEADERTYPE* pBuffer )
857 {
858 #ifdef  OMX_DETAILS
859   OMX_U32 omx_cnt;
860   unsigned long time;
861
862 #ifdef  CPU_LOAD_DETAILS
863   if( (kpi_status & KPI_CPU_TRACE) && !(kpi_status & KPI_IVA_USED) )
864   {
865     psi_cpu_load_details();   /* trace the Idle here unless already traced at IVA BEG time */
866   }
867 #endif//CPU_LOAD_DETAILS
868
869   if( kpi_omx_monitor_cnt == 0) return;
870
871   time = get_32k();
872
873   /* identify the component from the registery */
874   for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
875     if( kpi_omx_monitor[omx_cnt].hComponent == hComponent ) break;
876   }
877
878   /* Update counts and trace the event */
879   if( omx_cnt < MAX_OMX_COMP ) {
880     /* trace the event */
881     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "FBD %-7s %-4u %-8lu x%-8x\n",
882 #ifdef PHYSICAL_BUFFER
883       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_fbd, time, pBuffer->pBuffer );
884 #else
885       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_fbd, time, pBuffer );
886 #endif
887   }
888 #endif//OMX_DETAILS
889
890 }
891
892 /***************************************************************
893  * kpi_omx_comp_ETB
894  * -------------------------------------------------------------
895  * Trace EmptyThisBuffer() event
896  *
897  * @params: OMX_HANDLETYPE  hComponent
898  *          OMX_BUFFERHEADERTYPE* pBuffer
899  *
900  * @return: none
901  *
902  ***************************************************************/
903 void kpi_omx_comp_ETB( OMX_HANDLETYPE hComponent, OMX_BUFFERHEADERTYPE* pBuffer )
904 {
905 #ifdef  OMX_DETAILS
906   OMX_U32 omx_cnt;
907
908   if( kpi_omx_monitor_cnt == 0) return;
909
910   /* identify the component from the registery */
911   for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
912     if( kpi_omx_monitor[omx_cnt].hComponent == hComponent ) break;
913   }
914
915   /* Update counts and trace the event */
916   if( omx_cnt < MAX_OMX_COMP ) {
917     /* trace the event */
918     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "ETB %-7s %-4u %-8lu x%-8x\n",
919 #ifdef PHYSICAL_BUFFER
920       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_etb, get_32k(), pBuffer->pBuffer );
921 #else
922       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_etb, get_32k(), pBuffer );
923 #endif
924   }
925 #endif//OMX_DETAILS
926
927 }
928
929 /***************************************************************
930  * kpi_omx_comp_EBD
931  * -------------------------------------------------------------
932  * Trace EmptyBufferDone() event
933  *
934  * @params: OMX_HANDLETYPE hComponent
935  *          OMX_BUFFERHEADERTYPE* pBuffer
936  *
937  * @return: none
938  *
939  ***************************************************************/
940 void kpi_omx_comp_EBD( OMX_HANDLETYPE hComponent, OMX_BUFFERHEADERTYPE* pBuffer )
941 {
942 #ifdef  OMX_DETAILS
943   OMX_U32 omx_cnt;
944
945   if( kpi_omx_monitor_cnt == 0) return;
946
947   /* identify the component from the registery */
948   for( omx_cnt=0; omx_cnt < MAX_OMX_COMP;  omx_cnt++ ) {
949     if( kpi_omx_monitor[omx_cnt].hComponent == hComponent ) break;
950   }
951
952   /* Update counts and trace the event */
953   if( omx_cnt < MAX_OMX_COMP ) {
954     /* trace the event */
955     PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "EBD %-7s %-4u %-8lu x%-8x\n",
956 #ifdef PHYSICAL_BUFFER
957       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_ebd, get_32k(), pBuffer->pBuffer );
958 #else
959       kpi_omx_monitor[omx_cnt].name, ++kpi_omx_monitor[omx_cnt].count_ebd, get_32k(), pBuffer );
960 #endif
961   }
962 #endif//OMX_DETAILS
963
964 }
965
966
967 /***************************************************************
968  * kpi_load_pct_x_100
969  * -------------------------------------------------------------
970  * calculate percentage with 2 digit such as 78.34 %
971  *
972  * @params: unsigned long load, total
973  *
974  * @return: unsigned long result
975  *
976  ***************************************************************/
977 unsigned long kpi_load_pct_x_100(unsigned long load, unsigned long total)
978 {
979   unsigned long mult = 100 * 100;
980
981   while (total > (32768*8)) {
982     total /= 2;
983     mult /= 2;
984   }
985
986   /* load = 100 * 100 * load / total */
987   load = ((load * mult) + total/2) / total;
988   return (load);
989 }
990
991 /***************************************************************
992  * kpi_CPU_profiler_init
993  * -------------------------------------------------------------
994  * Initialize profiler data
995  *
996  * @params: none
997  *
998  * @return: none
999  *
1000  ***************************************************************/
1001 void kpi_CPU_profiler_init(void)
1002 {
1003   unsigned int CoreId, i;
1004
1005   PSI_TracePrintf( TIMM_OSAL_TRACEGRP_SYSTEM, "<KPI> CPU Profiler Init %-8lu\n", get_32k() );
1006
1007   for (CoreId = 0; CoreId < 2; CoreId++)
1008   {
1009     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1010
1011     core_kpi->total_time       = 0;
1012     core_kpi->kpi_time         = 0;
1013     core_kpi->kpi_count        = 0;
1014     core_kpi->nb_switch        = 0;
1015
1016     core_kpi->nb_tasks         = 0;
1017     core_kpi->nb_hwi           = 0;
1018     core_kpi->nb_swi           = 0;
1019
1020     core_kpi->tasks[0].handle  = 0;                             /* for startup set task[0].handle to 0 */
1021
1022     /* reserve last task slot in DB to others task that wouldn't fit in the DB */
1023     core_kpi->tasks[KPI_MAX_NB_TASKS-1].handle = (void*) 0x11000011;
1024     core_kpi->tasks[KPI_MAX_NB_TASKS-1].total_time = 0;
1025     core_kpi->tasks[KPI_MAX_NB_TASKS-1].nb_switch  = 0;
1026     strcpy(core_kpi->tasks[KPI_MAX_NB_TASKS-1].name, "Other tasks");
1027     /* reserve last swi slot in DB to others task that wouldn't fit in the DB */
1028     core_kpi->swi[KPI_MAX_NB_SWI-1].handle = (void*) 0x22000022;
1029     core_kpi->swi[KPI_MAX_NB_SWI-1].total_time = 0;
1030     core_kpi->swi[KPI_MAX_NB_SWI-1].nb_switch  = 0;
1031     strcpy(core_kpi->swi[KPI_MAX_NB_SWI-1].name, "Other swis");
1032     /* reserve last hwi slot in DB to others task that wouldn't fit in the DB */
1033     core_kpi->hwi[KPI_MAX_NB_HWI-1].handle = (void*) 0x33000033;
1034     core_kpi->hwi[KPI_MAX_NB_HWI-1].total_time = 0;
1035     core_kpi->hwi[KPI_MAX_NB_HWI-1].nb_switch  = 0;
1036     strcpy(core_kpi->hwi[KPI_MAX_NB_HWI-1].name, "Other hwis");
1037
1038     /* clear the context pointers table */
1039     for (i=0; i < CTX_DIRECT_NUM; i++) {
1040      core_kpi->context_cache[i]= &(core_kpi->tasks[0]);         /* point to the Data Base */
1041     }
1042
1043     core_kpi->context_stack[0] = &(core_kpi->tasks[0]);         /* point to 1st context element */
1044     core_kpi->pt_context_stack = &(core_kpi->context_stack[0]); /* stack beginning */
1045
1046     core_kpi->ptr_idle_total   = &(core_kpi->idle_prev);        /* will point later on to idle_total_ticks */
1047     core_kpi->idle_prev        = 0;
1048     core_kpi->idle_time_prev   = 0;
1049
1050     core_kpi->trace_time       = 0;
1051
1052   }
1053
1054   /* set current time into prev_t32 in each data based */
1055   bios_kpi[0].prev_t32 = get_time();
1056   bios_kpi[1].prev_t32 = bios_kpi[0].prev_t32;
1057
1058 }
1059
1060 /***************************************************************
1061  * kpi_CPU_profiler_print
1062  * -------------------------------------------------------------
1063  * Print profiler data
1064  *
1065  * @params: none
1066  *
1067  * @return: none
1068  *    if (prev != NULL)
1069
1070  ***************************************************************/
1071 void kpi_CPU_profiler_print(void)
1072 {
1073   unsigned long load, ld00, Idle, CoreId, i;
1074   psi_bios_kpi *core_kpi;
1075
1076 #ifdef  COST_AFTER
1077   unsigned long instx1024;
1078   /* calculate instrumentation cost a posteriori */
1079   {
1080     Task_Handle test;
1081     unsigned long key = Task_disable();
1082     core_kpi = &bios_kpi[ Core_getCoreId() ];
1083     test = core_kpi->tasks[0].handle;
1084     instx1024 = get_time();
1085     for(i = 0; i < 1024; i++) psi_kpi_task_test( test, test );
1086     instx1024 = get_time()-instx1024;
1087     Task_restore(key);
1088   }
1089 #endif//COST_AFTER
1090
1091   /* Print the results for each core */
1092   for (CoreId = 0; CoreId < 2; CoreId++ ) {
1093     core_kpi = &bios_kpi[CoreId];
1094
1095     /* Reconstruct global counts */
1096     for (i=0; i < core_kpi->nb_tasks; i++){
1097       core_kpi->nb_switch += core_kpi->tasks[i].nb_switch;     /* nb_switch  (nb interrupts + task switchs) */
1098       core_kpi->kpi_count += core_kpi->tasks[i].nb_switch;     /* kpi_count (nunber of times the intrumentation run) */
1099       core_kpi->total_time+= core_kpi->tasks[i].total_time;    /* total_time (all times measured) */
1100     }
1101     for (i=0; i < core_kpi->nb_swi; i++) {
1102       core_kpi->nb_switch += core_kpi->swi[i].nb_switch;
1103       core_kpi->kpi_count += core_kpi->swi[i].nb_switch * 2;   /* 2 runs per interrupts */
1104       core_kpi->total_time+= core_kpi->swi[i].total_time;
1105     }
1106     for (i=0; i < core_kpi->nb_hwi; i++) {
1107       core_kpi->nb_switch += core_kpi->hwi[i].nb_switch;
1108       core_kpi->kpi_count += core_kpi->hwi[i].nb_switch * 2;   /* 2 runs per interrupts */
1109       core_kpi->total_time+= core_kpi->hwi[i].total_time;
1110     }
1111     /* add cost of measured if stored as a separate task */
1112     core_kpi->total_time += core_kpi->kpi_time;
1113
1114     if ( core_kpi->total_time ) {
1115       /* Print global stats */
1116       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
1117       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "Core %d :\n", CoreId);
1118       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "--------\n");
1119       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  type  #: handle   ticks    counts  ( %%cpu )   instance-name\n");
1120       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
1121       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  Total test        %-8lu %-7ld\n", core_kpi->total_time, core_kpi->nb_switch);
1122       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
1123
1124       if( core_kpi->kpi_time )
1125       {
1126         ld00 = kpi_load_pct_x_100(core_kpi->kpi_time, core_kpi->total_time);/* ex. 7833 -> 78.33 % */
1127         load = ld00/100;                                                  /* 78.33 % -> 78 */
1128         ld00 = ld00 - load*100;                                           /* 78.33 % -> 33 */
1129         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  Measure: Overhead %-8lu ----    (%2d.%02d %%)  CPU load-inst-cost\n",
1130           core_kpi->kpi_time, load, ld00);
1131       }
1132
1133       for (i=0; i < core_kpi->nb_tasks; i++)
1134       {
1135         ld00 = kpi_load_pct_x_100(core_kpi->tasks[i].total_time, core_kpi->total_time);
1136         load = ld00/100;                                                /* 78.33 % -> 78 */
1137         ld00 = ld00 - load*100;                                         /* 78.33 % -> 33 */
1138         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  task %2d: %-8lx %-8lu %-7ld (%2d.%02d %%)  %s\n",
1139           i, core_kpi->tasks[i].handle, core_kpi->tasks[i].total_time, core_kpi->tasks[i].nb_switch, load, ld00, core_kpi->tasks[i].name);
1140       }
1141
1142       for (i=0; i < core_kpi->nb_swi; i++)
1143       {
1144         ld00 = kpi_load_pct_x_100(core_kpi->swi[i].total_time, core_kpi->total_time);
1145         load = ld00/100;                                                /* 78.33 % -> 78 */
1146         ld00 = ld00 - load*100;                                         /* 78.33 % -> 33 */
1147         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "   swi %2d: %-8lx %-8lu %-7ld (%2d.%02d %%)  %s\n",
1148           i, core_kpi->swi[i].handle, core_kpi->swi[i].total_time, core_kpi->swi[i].nb_switch, load, ld00, core_kpi->swi[i].name);
1149       }
1150
1151       for (i=0; i < core_kpi->nb_hwi; i++)
1152       {
1153         ld00 = kpi_load_pct_x_100(core_kpi->hwi[i].total_time, core_kpi->total_time);
1154         load = ld00/100;                                                /* 78.33 % -> 78 */
1155         ld00 = ld00 - load*100;                                         /* 78.33 % -> 33 */
1156         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "   hwi %2d: %-8lx %-8lu %-7ld (%2d.%02d %%)  %s\n",
1157           i, core_kpi->hwi[i].handle, core_kpi->hwi[i].total_time, core_kpi->hwi[i].nb_switch, load, ld00, core_kpi->hwi[i].name);
1158       }
1159
1160       PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
1161
1162 #ifdef  COST_AFTER
1163       if( !core_kpi->kpi_time )
1164       {
1165         /* calculate the cost in the instrumentation */
1166         core_kpi->kpi_time = (core_kpi->kpi_count * instx1024) / 1024;
1167         ld00 = kpi_load_pct_x_100(core_kpi->kpi_time, core_kpi->total_time);/* ex. 7833 -> 78.33 % */
1168         load = ld00/100;                                                  /* 78.33 % -> 78 */
1169         ld00 = ld00 - load*100;                                           /* 78.33 % -> 33 */
1170         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  CPU load measure overhead  %2d.%02d %%\n", load, ld00);
1171       }
1172 #endif//COST_AFTER
1173
1174       if( core_kpi->trace_time )
1175       {
1176         ld00 = kpi_load_pct_x_100(core_kpi->trace_time, core_kpi->total_time);
1177         load = ld00/100;                                                /* 78.33 % -> 78 */
1178         ld00 = ld00 - load*100;                                         /* 78.33 % -> 33 */
1179         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  Real time traces overhead  %2d.%02d %%\n", load, ld00);
1180       }
1181
1182       /* restore to Idle Inst cost + print cost if idle exists */
1183       if( *(core_kpi->ptr_idle_total) )
1184       {
1185         Idle = *(core_kpi->ptr_idle_total) + core_kpi->kpi_time + core_kpi->trace_time;
1186         ld00 = kpi_load_pct_x_100(Idle, core_kpi->total_time);
1187         load = ld00/100;                                                /* 78.33 % -> 78 */
1188         ld00 = ld00 - load*100;                                         /* 78.33 % -> 33 */
1189         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n");
1190         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "  Idle task compensated  =>  %2d.%02d %% \n", load, ld00);
1191         PSI_TracePrintf(TIMM_OSAL_TRACEGRP_SYSTEM, "----------------------------------\n\n");
1192       }
1193
1194     }
1195   }
1196
1197 }
1198
1199
1200 /***************************************************************
1201  * psi_kpi_search_create_context_task
1202  * -------------------------------------------------------------
1203  * Search for a context entry to context DB.
1204  * Create a new on if not existing
1205  *
1206  * @params: void *task, unsigned int CoreId
1207  *
1208  * @return: psi_context_info *db_ptr
1209  *
1210  ***************************************************************/
1211 psi_context_info *psi_kpi_search_create_context_task(void *task, psi_bios_kpi *core_kpi)
1212 {
1213   int i, nb_items, strLenght;
1214   String taskName;
1215   psi_context_info *db_ptr;
1216
1217   /* KPI_CONTEXT_TASK */
1218   nb_items = core_kpi->nb_tasks;
1219   db_ptr   = core_kpi->tasks;
1220
1221   /* Search handle existing in task table */
1222   for (i=0; i < nb_items; i++) {
1223     if (task == db_ptr[i].handle) break;
1224   }
1225
1226   /* handle found in our DB */
1227   if( i < nb_items ) {
1228     return (&db_ptr[i]);
1229   }
1230
1231   /* check for space left in the DB. When last-1 reached use last for others tasks together */
1232   if (nb_items >= KPI_MAX_NB_TASKS-1) {
1233     core_kpi->nb_tasks = KPI_MAX_NB_TASKS;
1234     return (&db_ptr[KPI_MAX_NB_TASKS-1]);
1235   }
1236
1237   /* add the new task */
1238   core_kpi->nb_tasks = nb_items+1;
1239
1240   /* get the task name Make sure task name fits into the item.name */
1241   taskName = Task_Handle_name((Task_Handle)task);
1242   strLenght = strlen( taskName );
1243   if (strLenght > 40 ) strLenght = 40;
1244
1245   /* For Idle direct access */
1246   if( strstr(taskName, "Idle") )
1247     core_kpi->ptr_idle_total = &(db_ptr[i].total_time);
1248
1249   /* create the new entry */
1250   db_ptr[i].handle     = task;
1251   db_ptr[i].total_time = 0;
1252   db_ptr[i].nb_switch  = 0;
1253   strncpy(db_ptr[i].name, taskName, strLenght);
1254   *(db_ptr[i].name + strLenght) = '\0';                  // complete the chain of char
1255
1256   return &(db_ptr[i]);
1257 }
1258
1259 /***************************************************************
1260  * psi_kpi_search_create_context_swi
1261  * -------------------------------------------------------------
1262  * Search for a context entry to context DB.
1263  * Create a new on if not existing
1264  *
1265  * @params: void *task, unsigned int CoreId
1266  *
1267  * @return: psi_context_info *db_ptr
1268  *
1269  ***************************************************************/
1270 psi_context_info *psi_kpi_search_create_context_swi(void *task, psi_bios_kpi *core_kpi)
1271 {
1272   int i, nb_items, strLenght;
1273   String taskName;
1274   psi_context_info *db_ptr;
1275
1276   /* KPI_CONTEXT_SWI */
1277   nb_items = core_kpi->nb_swi;
1278   db_ptr   = core_kpi->swi;
1279
1280   /* Search handle existing in task table */
1281   for (i=0; i < nb_items; i++) {
1282     if (task == db_ptr[i].handle) break;
1283   }
1284
1285   /* handle found in our DB */
1286   if( i < nb_items ) {
1287     return (&db_ptr[i]);
1288   }
1289
1290   /* check for space left in the DB. When last-1 reached use last for others swi together */
1291   if (nb_items >= KPI_MAX_NB_SWI-1) {
1292     core_kpi->nb_swi = KPI_MAX_NB_SWI;
1293     return (&db_ptr[KPI_MAX_NB_SWI-1]);
1294   }
1295
1296   /* add the new swi */
1297   core_kpi->nb_swi = nb_items+1;
1298
1299   /* get the task name Make sure task name fits into the item.name */
1300   taskName = Swi_Handle_name((Swi_Handle)task);
1301   strLenght = strlen( taskName );
1302   if (strLenght > 40 ) strLenght = 40;
1303
1304   /* create the new entry */
1305   db_ptr[i].handle     = task;
1306   db_ptr[i].total_time = 0;
1307   db_ptr[i].nb_switch  = 0;
1308   strncpy(db_ptr[i].name, taskName, strLenght);
1309   *(db_ptr[i].name + strLenght) = '\0';                  // complete the chain of char
1310
1311   return &(db_ptr[i]);
1312 }
1313
1314 /***************************************************************
1315  * psi_kpi_search_create_context_hwi
1316  * -------------------------------------------------------------
1317  * Search for a context entry to context DB.
1318  * Create a new on if not existing
1319  *
1320  * @params: void *task, unsigned int CoreId
1321  *
1322  * @return: psi_context_info *db_ptr
1323  *
1324  ***************************************************************/
1325 psi_context_info *psi_kpi_search_create_context_hwi(void *task, psi_bios_kpi *core_kpi)
1326 {
1327   int i, nb_items, strLenght;
1328   String taskName;
1329   psi_context_info *db_ptr;
1330
1331   /* KPI_CONTEXT_HWI */
1332   nb_items = core_kpi->nb_hwi;
1333   db_ptr   = core_kpi->hwi;
1334
1335   /* Search handle existing in task table */
1336   for (i=0; i < nb_items; i++) {
1337     if (task == db_ptr[i].handle) break;
1338   }
1339
1340   /* handle found in our DB */
1341   if( i < nb_items ) {
1342     return (&db_ptr[i]);
1343   }
1344
1345   /* check for space left in the DB. When last-1 reached use last for others hwi together */
1346   if (nb_items >= KPI_MAX_NB_HWI-1) {
1347     core_kpi->nb_hwi = KPI_MAX_NB_HWI;
1348     return (&db_ptr[KPI_MAX_NB_HWI-1]);
1349   }
1350
1351   /* add the new hwi */
1352   core_kpi->nb_hwi = nb_items+1;
1353
1354   /* get the task name Make sure task name fits into the item.name */
1355   taskName = Hwi_Handle_name((Hwi_Handle)task);
1356   strLenght = strlen( taskName );
1357   if (strLenght > 40 ) strLenght = 40;
1358
1359   /* create the new entry */
1360   db_ptr[i].handle     = task;
1361   db_ptr[i].total_time = 0;
1362   db_ptr[i].nb_switch  = 0;
1363   strncpy(db_ptr[i].name, taskName, strLenght);
1364   *(db_ptr[i].name + strLenght) = '\0';                  // complete the chain of char
1365
1366   return &(db_ptr[i]);
1367 }
1368
1369 /***************************************************************
1370  * psi_kpi_task_switch
1371  * -------------------------------------------------------------
1372  * Task switch hook:
1373  *  - identify new tasks
1374  *  - accumulate task load
1375  *  - process total execution time
1376  *
1377  * @params: Task_Handle prev, Task_Handle next
1378  *
1379  * @return: none
1380  *
1381  ***************************************************************/
1382 void psi_kpi_task_switch(Task_Handle prev, Task_Handle next)
1383 {
1384   if ( kpi_status & KPI_CPU_LOAD )
1385   {
1386     unsigned long key    = Hwi_disableCoreInts();
1387     unsigned long CoreId = Core_getCoreId();
1388     unsigned long tick   = get_time_core(CoreId);
1389     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1390     psi_context_info *context_next, *context;
1391     unsigned long cachePtr;
1392
1393     /* Ending context */
1394     context = (psi_context_info *) *core_kpi->pt_context_stack;
1395
1396     /* Starting context */
1397     cachePtr= ((((long) next)>>4) ^ (((long) next)>>12) ) & 0xff; /* build a simple 8 bits address for trying cache DB search */
1398     context_next = core_kpi->context_cache[ cachePtr ];
1399     if (context_next->handle != next) {                           /* if NOT pointing to our handle make exhaustive seartch */
1400       context_next = psi_kpi_search_create_context_task(next, core_kpi);
1401       core_kpi->context_cache[ cachePtr ] = context_next;         /* update direct table (this may evict one already here) */
1402     }
1403
1404     /* Maintain stack for interrupts: save context starting */
1405     *core_kpi->pt_context_stack = (void*) context_next;
1406
1407     /* update tasks stats */
1408     context->total_time  += tick - core_kpi->prev_t32;            /* count the time spend in the ending task */
1409     context->nb_switch   ++;                                      /* count the switch */
1410
1411 #ifdef  INST_COST
1412     /* will start processing the task now */
1413     {
1414       unsigned long tick2 = get_time_core(CoreId);
1415       core_kpi->kpi_time += tick2 - tick;                         /* update kpi_time (instrumentation cost) */
1416       core_kpi->prev_t32  = tick2;                                /* store tick: time when task actually starts */
1417     }
1418 #else //INST_COST
1419     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1420 #endif//INST_COST
1421
1422     Hwi_restoreCoreInts( key );
1423   }
1424 }
1425
1426 /***************************************************************
1427  * psi_kpi_swi_begin
1428  * -------------------------------------------------------------
1429  * SWI begin hook: memorizes SWI start time
1430  *
1431  * @params: Swi_Handle swi
1432  *
1433  * @return: none
1434  *
1435  ***************************************************************/
1436 void psi_kpi_swi_begin(Swi_Handle swi)
1437 {
1438   if ( kpi_status & KPI_CPU_LOAD )
1439   {
1440     unsigned long key    = Hwi_disableCoreInts();
1441     unsigned long CoreId = Core_getCoreId();
1442     unsigned long tick   = get_time_core(CoreId);
1443     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1444     psi_context_info *context_next, *context;
1445     unsigned long cachePtr;
1446
1447     /* Ending context */
1448     context = (psi_context_info *) *core_kpi->pt_context_stack++; /* Going from a TASK or SWI to new SWI */
1449
1450     /* Starting context */
1451     cachePtr= ((((long) swi)>>4) ^ (((long) swi)>>12) ) & 0xff;   /* build a simple 8 bits address for trying cache DB search */
1452     context_next = core_kpi->context_cache[ cachePtr ];
1453     if (context_next->handle != swi) {                            /* if NOT pointing to our handle make exhaustive seartch */
1454       context_next = psi_kpi_search_create_context_swi(swi, core_kpi);
1455       core_kpi->context_cache[ cachePtr ] = context_next;         /* update direct table (this may evict one already here) */
1456     }
1457
1458     /* Maintain stack for interrupts: save context starting */
1459     *core_kpi->pt_context_stack = (void*) context_next;
1460
1461     /* update tasks stats */
1462     context->total_time  += tick - core_kpi->prev_t32;            /* count the time spend in the ending task */
1463
1464 #ifdef  INST_COST
1465     /* will start processing the task now */
1466     {
1467       unsigned long tick2 = get_time_core(CoreId);
1468       core_kpi->kpi_time += tick2 - tick;                         /* update kpi_time (instrumentation cost) */
1469       core_kpi->prev_t32  = tick2;                                /* store tick: time when task actually starts */
1470     }
1471 #else //INST_COST
1472     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1473 #endif//INST_COST
1474
1475     Hwi_restoreCoreInts( key );
1476   }
1477 }
1478
1479 /***************************************************************
1480  * psi_kpi_swi_end
1481  * -------------------------------------------------------------
1482  * SWI end hook: accumulates SWI execution time
1483  *
1484  * @params: Swi_Handle swi
1485  *
1486  * @return: none
1487  *
1488  ***************************************************************/
1489 void psi_kpi_swi_end(Swi_Handle swi)
1490 {
1491   if ( kpi_status & KPI_CPU_LOAD )
1492   {
1493     unsigned long key    = Hwi_disableCoreInts();
1494     unsigned long CoreId = Core_getCoreId();
1495     unsigned long tick   = get_time_core(CoreId);
1496     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1497     psi_context_info *context;
1498
1499     /* Ending context */
1500     context = (psi_context_info *) *core_kpi->pt_context_stack--; /* Going back to interrupted TASK or SWI */
1501
1502     /* update tasks stats */
1503     context->total_time  += tick - core_kpi->prev_t32;            /* count the time spend in the ending task */
1504     context->nb_switch   ++;                                      /* count the switch */
1505
1506 #ifdef  INST_COST
1507     /* will start processing the task now */
1508     {
1509       unsigned long tick2 = get_time_core(CoreId);
1510       core_kpi->kpi_time += tick2 - tick;                         /* update kpi_time (instrumentation cost) */
1511       core_kpi->prev_t32  = tick2;                                /* store tick: time when task actually starts */
1512     }
1513 #else //INST_COST
1514     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1515 #endif//INST_COST
1516
1517     Hwi_restoreCoreInts( key );
1518   }
1519 }
1520
1521 /***************************************************************
1522  * psi_kpi_hwi_begin
1523  * -------------------------------------------------------------
1524  * HWI begin hook: memorizes HWI start time
1525  *
1526  * @params: Hwi_Handle hwi
1527  *
1528  * @return: none
1529  *
1530  ***************************************************************/
1531 void psi_kpi_hwi_begin(Hwi_Handle hwi)
1532 {
1533   if ( kpi_status & KPI_CPU_LOAD )
1534   {
1535     unsigned long key    = Hwi_disableCoreInts();
1536     unsigned long CoreId = Core_getCoreId();
1537     unsigned long tick   = get_time_core(CoreId);
1538     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1539     psi_context_info *context_next, *context;
1540     unsigned long cachePtr;
1541
1542     /* Ending context */
1543     context = (psi_context_info *) *core_kpi->pt_context_stack++; /* Going from previous TASK or SWI to a HWI */
1544
1545     /* Starting context */
1546     cachePtr= ((((long) hwi)>>4) ^ (((long) hwi)>>12) ) & 0xff;   /* build a simple 8 bits address for trying cache DB search */
1547     context_next = core_kpi->context_cache[ cachePtr ];
1548     if (context_next->handle != hwi) {                            /* if NOT pointing to our handle make exhaustive seartch */
1549       context_next = psi_kpi_search_create_context_hwi(hwi, core_kpi);
1550       core_kpi->context_cache[ cachePtr ] = context_next;         /* update direct table (this may evict one already here) */
1551     }
1552
1553     /* Maintain stack for interrupts: save context starting */
1554     *core_kpi->pt_context_stack = (void*) context_next;
1555
1556     /* update tasks stats */
1557     context->total_time  += tick - core_kpi->prev_t32;            /* count the time spend in the ending task */
1558
1559 #ifdef  INST_COST
1560     /* will start processing the task now */
1561     {
1562       unsigned long tick2 = get_time_core(CoreId);
1563       core_kpi->kpi_time += tick2 - tick;                         /* update kpi_time (instrumentation cost) */
1564       core_kpi->prev_t32  = tick2;                                /* store tick: time when task actually starts */
1565     }
1566 #else //INST_COST
1567     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1568 #endif//INST_COST
1569
1570     Hwi_restoreCoreInts( key );
1571   }
1572 }
1573
1574 /***************************************************************
1575  * psi_kpi_hwi_end
1576  * -------------------------------------------------------------
1577  * HWI end hook: accumulates HWI execution time
1578  *
1579  * @params: Hwi_Handle hwi
1580  *
1581  * @return: none
1582  *
1583  ***************************************************************/
1584 void psi_kpi_hwi_end(Hwi_Handle hwi)
1585 {
1586   if ( kpi_status & KPI_CPU_LOAD )
1587   {
1588     unsigned long key    = Hwi_disableCoreInts();
1589     unsigned long CoreId = Core_getCoreId();
1590     unsigned long tick   = get_time_core(CoreId);
1591     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1592     psi_context_info *context;
1593
1594     /* Ending context */
1595     context = (psi_context_info *) *core_kpi->pt_context_stack--; /* Going back to interrupted TASK or SWI or HWI */
1596
1597     /* update tasks stats */
1598     context->total_time  += tick - core_kpi->prev_t32;            /* count the time spend in the ending task */
1599     context->nb_switch   ++;                                      /* count the switch */
1600
1601 #ifdef  INST_COST
1602     /* will start processing the task now */
1603     {
1604       unsigned long tick2 = get_time_core(CoreId);
1605       core_kpi->kpi_time += tick2 - tick;                         /* update kpi_time (instrumentation cost) */
1606       core_kpi->prev_t32  = tick2;                                /* store tick: time when task actually starts */
1607     }
1608 #else //INST_COST
1609     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1610 #endif//INST_COST
1611
1612     Hwi_restoreCoreInts( key );
1613   }
1614 }
1615
1616 /***************************************************************
1617  * psi_kpi_task_test
1618  * -------------------------------------------------------------
1619  * Task switch hook:
1620  *  - identify new tasks
1621  *  - used for measuring execution time of the instrumentation
1622  *
1623  * @params: Task_Handle prev, Task_Handle next
1624  *
1625  * @return: none
1626  *
1627  ***************************************************************/
1628 void psi_kpi_task_test(Task_Handle prev, Task_Handle next)
1629 {
1630     unsigned long key    = Hwi_disableCoreInts();
1631     unsigned long CoreId = Core_getCoreId();
1632     unsigned long tick   = get_time_core(CoreId);
1633     psi_bios_kpi *core_kpi = &bios_kpi[CoreId];
1634     psi_context_info *context_next;
1635     unsigned long cachePtr;
1636
1637     /* Starting context */
1638     cachePtr= ((((long) next)>>4) ^ (((long) next)>>12) ) & 0xff; /* build a simple 8 bits address for trying cache DB search */
1639     context_next = core_kpi->context_cache[ cachePtr ];
1640     if (context_next->handle != next) {                           /* if NOT pointing to our handle make exhaustive seartch */
1641       context_next = psi_kpi_search_create_context_task(next, core_kpi);
1642       core_kpi->context_cache[ cachePtr ] = context_next;         /* update direct table (this may evict one already here) */
1643     }
1644
1645     /* Maintain stack for interrupts: save context starting */
1646     *core_kpi->pt_context_stack = (void*) context_next;
1647
1648     core_kpi->prev_t32    = tick;                                 /* store tick: time when task actually starts */
1649
1650     Hwi_restoreCoreInts( key );
1651 }
1652
1653
1654