Profiling your Retro68 application

Profiling your Retro68 application using serialperformanceanalyzer

When moving Nuklear to Macintosh, it became apparent that there would be a lot of performance optimization work necessary to provide a usable GUI experience on an 8MHz Macintosh. To make the situation worse, there is no profiling tooling available for Retro68, and no way as far as I could tell to run some kind of code profiler against the pce-macplus emulator, so I came up with a simple library for profiling code over a serial port via simple function calls.

So let’s say you’re wanting to profile a Retro68 application that you’re working on. Here’s how you might go about that.

As I outlined in the README for serialperformanceanalyzer, it is a nodejs script that runs on a host machine (at the end of a serial port) and accepts 3 types of messages:

  • PROFILE_START x - starts tracking x
  • PROFILE_END x - stops tracking x. Measures and stores how long x took to run
  • PROFILE_COMPLETE - analyzes all profile data and prints it out in 3 charts

serialperformanceanalyzer tracks and charts 3 things:

  • Count of profile marks hit
  • Most total time spent in each profile mark overall
  • Longest individual profile mark

Setting up your code

Next on the Retro68 C application side, I recommend setting up a distinct serial port logging function as well as some helper functions and putting everything behind a flag. Here’s how I set that up in my programs:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
#define PROFILING 1
#ifdef PROFILING

OSErr writeSerialPortProfile(const char* str)
{

    #define PRINTER_PORT_OUT "\p.BOut"

    OSErr err;
    short serialPort = 0;
    err = OpenDriver(PRINTER_PORT_OUT, &serialPort);    
    if (err < 0) return err;    
    
    CntrlParam cb2;
    cb2.ioCRefNum = serialPort;
    cb2.csCode = 8;
    cb2.csParam[0] = stop10 | noParity | data8 | baud9600;
    err = PBControl ((ParmBlkPtr) & cb2, 0);    
    if (err < 0) return err; 
            
    IOParam pb2;
    pb2.ioRefNum = serialPort;
    
    char str2[1024];
    sprintf(str2, "%s\n", str);
    pb2.ioBuffer = (Ptr) str2;
    pb2.ioReqCount = strlen(str2);
    
    err = PBWrite((ParmBlkPtr)& pb2, 0);          
    if (err < 0) return err;
    
    // hangs on Mac512K (write hasn't finished due to slow Speed when we wants to close driver
    // err = CloseDriver(serialPort);
    
    return err;
}

void PROFILE_START(char *name) {

    char profileMessage[255];
    sprintf(profileMessage, "PROFILE_START %s", name);

    writeSerialPortProfile(profileMessage);

    return;
}

void PROFILE_END(char *name) {

    char profileMessage[255];
    sprintf(profileMessage, "PROFILE_END %s", name);

    writeSerialPortProfile(profileMessage);

    return;
}

void PROFILE_COMPLETE() {

    writeSerialPortProfile("PROFILE_COMPLETE");

    return;
}

#endif

What does this give us?

  • A PROFILING flag to turn on and off for profiling our app. We should put every piece of profiling we want to add in tags like this (the profile messages are really going to slow things down)
  • PROFILE_START, PROFILE_END, PROFILE_COMPLETE functions to call in our C code to correspond with the messages that serialperformanceanalyzer is watching for

So what can we do next? Start honing in on slow code!

To do that, we can do things like this throughout our code:

1
2
3
4
5
6
7
8
9
#ifdef PROFILING
    PROFILE_START("suspected slow code 1");
#endif

...

#ifdef PROFILING
    PROFILE_END("suspected slow code 1");
#endif

And as long as we have matching PROFILE_START and PROFILE_END statements, serialperformanceanalyzer will provide us with a measurement.

Last, to have serialperformanceanalyzer produce results, we must call PROFILE_COMPLETE. I recommend adding:

1
2
3
#ifdef PROFILING
    PROFILE_COMPLETE();
#endif

to the Terminate function, which be called by the File > Quit menu option. This will trigger the serialperformanceanalyzer application to run its analysis and print out results.

Results

Here are what some example results look like. This output should display in the terminal window that you are running serialperformanceanalyzer in assuming it is pointed to the right serial port. This example is using the PROFILING variable turned on in nuklear-quickdraw, which has provisioning to use serialperformanceanalyzer already in place.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
Total calls  
rendering loop and switch: 8 ╢■■■■■■■■■■■■■■■■■■■■■■■■■
          memcpy commands: 8 ╢■■■■■■■■■■■■■■■■■■■■■■■■■
                copy bits: 8 ╢■■■■■■■■■■■■■■■■■■■■■■■■■
            nk_input_end: 15 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
              nuklearApp: 15 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
     nk_quickdraw_render: 15 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
                nk_clear: 15 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  IN nk_quickdraw_render: 16 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
get cmds and memcmp them: 16 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
                             ╚══════════════════════════════════════════════════
Total time  
           memcpy commands: 151 ╢■■
  get cmds and memcmp them: 168 ╢■■
                  nk_clear: 209 ╢■■■
              nk_input_end: 249 ╢■■■
                nuklearApp: 895 ╢■■■■■■■■■■■■
rendering loop and switch: 1193 ╢■■■■■■■■■■■■■■■■
                copy bits: 1226 ╢■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 3335 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 3815 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
                                ╚══════════════════════════════════════════════════
Time per call  
                   nk_clear: 3 ╢
                   nk_clear: 4 ╢
                  nk_clear: 13 ╢■
                  nk_clear: 14 ╢■
              nk_input_end: 15 ╢■■
              nk_input_end: 15 ╢■■
              nk_input_end: 15 ╢■■
              nk_input_end: 15 ╢■■
                  nk_clear: 15 ╢■■
                  nk_clear: 15 ╢■■
                  nk_clear: 15 ╢■■
                  nk_clear: 15 ╢■■
                  nk_clear: 15 ╢■■
           memcpy commands: 16 ╢■■
           memcpy commands: 16 ╢■■
              nk_input_end: 16 ╢■■
              nk_input_end: 16 ╢■■
              nk_input_end: 16 ╢■■
                  nk_clear: 16 ╢■■
                  nk_clear: 16 ╢■■
                  nk_clear: 16 ╢■■
                  nk_clear: 16 ╢■■
  get cmds and memcmp them: 17 ╢■■
           memcpy commands: 17 ╢■■
           memcpy commands: 17 ╢■■
           memcpy commands: 17 ╢■■
              nk_input_end: 17 ╢■■
              nk_input_end: 17 ╢■■
              nk_input_end: 17 ╢■■
  get cmds and memcmp them: 18 ╢■■
  get cmds and memcmp them: 18 ╢■■
              nk_input_end: 18 ╢■■
              nk_input_end: 18 ╢■■
              nk_input_end: 18 ╢■■
              nk_input_end: 18 ╢■■
              nk_input_end: 18 ╢■■
                  nk_clear: 18 ╢■■
                  nk_clear: 18 ╢■■
  get cmds and memcmp them: 19 ╢■■
  get cmds and memcmp them: 19 ╢■■
           memcpy commands: 19 ╢■■
           memcpy commands: 19 ╢■■
  get cmds and memcmp them: 21 ╢■■
  get cmds and memcmp them: 28 ╢■■■
  get cmds and memcmp them: 28 ╢■■■
           memcpy commands: 30 ╢■■■
                nuklearApp: 48 ╢■■■■■
                nuklearApp: 50 ╢■■■■■
                nuklearApp: 56 ╢■■■■■■
                nuklearApp: 56 ╢■■■■■■
                nuklearApp: 57 ╢■■■■■■
                nuklearApp: 58 ╢■■■■■■
                nuklearApp: 60 ╢■■■■■■
                nuklearApp: 60 ╢■■■■■■
                nuklearApp: 62 ╢■■■■■■
                nuklearApp: 62 ╢■■■■■■
                nuklearApp: 62 ╢■■■■■■
                nuklearApp: 62 ╢■■■■■■
                nuklearApp: 64 ╢■■■■■■■
       nk_quickdraw_render: 65 ╢■■■■■■■
                nuklearApp: 66 ╢■■■■■■■
       nk_quickdraw_render: 66 ╢■■■■■■■
       nk_quickdraw_render: 66 ╢■■■■■■■
       nk_quickdraw_render: 68 ╢■■■■■■■
                nuklearApp: 72 ╢■■■■■■■
       nk_quickdraw_render: 72 ╢■■■■■■■
       nk_quickdraw_render: 77 ╢■■■■■■■■
       nk_quickdraw_render: 77 ╢■■■■■■■■
       nk_quickdraw_render: 79 ╢■■■■■■■■
rendering loop and switch: 138 ╢■■■■■■■■■■■■■■
rendering loop and switch: 143 ╢■■■■■■■■■■■■■■■
rendering loop and switch: 143 ╢■■■■■■■■■■■■■■■
rendering loop and switch: 144 ╢■■■■■■■■■■■■■■■
rendering loop and switch: 144 ╢■■■■■■■■■■■■■■■
                copy bits: 144 ╢■■■■■■■■■■■■■■■
rendering loop and switch: 145 ╢■■■■■■■■■■■■■■■
                copy bits: 152 ╢■■■■■■■■■■■■■■■■
                copy bits: 152 ╢■■■■■■■■■■■■■■■■
                copy bits: 153 ╢■■■■■■■■■■■■■■■■
                copy bits: 154 ╢■■■■■■■■■■■■■■■■
                copy bits: 155 ╢■■■■■■■■■■■■■■■■
                copy bits: 156 ╢■■■■■■■■■■■■■■■■
rendering loop and switch: 158 ╢■■■■■■■■■■■■■■■■
                copy bits: 160 ╢■■■■■■■■■■■■■■■■
rendering loop and switch: 178 ╢■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 398 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 411 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 411 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 414 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 416 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 420 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 424 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   IN nk_quickdraw_render: 441 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 447 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 457 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 458 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 462 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 463 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 470 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
      nk_quickdraw_render: 488 ╢■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
                               ╚══════════════════════════════════════════════════

Did you enjoy my post?

I'm really excited about the work that I'm doing here. If you enjoyed my post and my work, please consider tipping me with a coffee. I appreciate you taking the time to read my post!

Page View

Comments

2021-12-21
⬆︎top