Tuesday, July 28, 2015

Learning to Profile a Go Application (pprof Fun)

I had previously written about a mini-application I used to test modulo vs looping performance. I thought, in the spirit of learning more about programming practices, I should try my hand at profiling the application as well. Maybe it would give some insight in how to analyze application performance!

I'll get this out of the way first. Most of the steps I'll review here work on the Mac. Except the output is broken, as of Go version 1.4.2. According to what I found online, it's a kernel bug with Darwin, not a flaw in Go. So in my case, I'm not going to use Darwin to profile application performance.

I should probably note that this is probably for the best anyway; some of the output options really want dot, from graphviz, installed in order to work, and getting it installed on the Mac was a little bit of a pain.

Now on to profiling

After discovering this little glitch with the Mac, I copied the source code to a Raspberry Pi. That way it's running under a version of Linux, and if anything shows performance issues, it would probably be the poor little Pi's processor (even though there could be performance differences due to the processor architecture. I'm kind of hoping a bottleneck in simple code is a bottleneck no matter the platform...just mentioning this as a warning to consider.)

As I previously mentioned, some of pprof's output really loves using graphviz, so that was the first thing to install. On the Pi I just used apt to grab it from the repo.

sudo apt-get install graphviz

Now I focused on the Go code. I created the application's directory under src and copied the loopcheck file into it. Next, I pulled the profile package from Dave Cheney into my pkg list.

go get github.com/davecheney/profile

This has moved. Use this command...
go get github.com/pkg/profile

Then I insert some references in the source. In my import list, I included:

import(
     //current imports...
     "github.com/davecheney/profile"
     "github.com/pkg/profile"
)

and the first line in Main() was:

     // Profiling!
     defer profile.Start(profile.CPUProfile).Stop()

Last step in prepping the application:

go install

That's all there is to it for prepping your application to grab CPU profiles. I think "go build" would also work, but this outlines I how did it.

NEXT I discovered yet another oddity. The test runs were fast. Like, really really fast, compared to my bigger-horsepower Mac. I added a quick line of code to print out the numbers being randomly generated and discovered that the Mac was generating int64's for my test cases, while the pi was generating (and casting to int64) int32 numbers. 

Now, I knew the Mac was generating really big numbers. For my purposes I needed really big numbers to loop through, so it wasn't a big deal. But now I see that on the Pi, it's actually following the rules of expected behavior, which wasn't what I had come to expect.

See if you can make sense of that statement.

I asked about it on StackOverflow, and as I suspected, it was the processor that made the difference. Meh, not a problem. I edited the source to be explicit and "correct." The previous blog post is using the incorrect (unexpected) behavior, so I guess this one is more "correct." Now I was going to deal with 32 bit numbers case into a 64 bit type (again, to better align with what I was testing in the actual program this was a test case for...)

I ran the program, and it generated a profile in /tmp. I next copied it to my working directory.

cp /tmp/profile510472042/cpu.pprof ./cpu_10000_serial_verbose.pprof

The location of the profile was initially printed to the console when I ran the program, but I also knew it was in /tmp/profile*, so finding it wasn't difficult. The name I used for the local copy reflects how I ran the application so I knew the codepath execution took.

Final step is to generate some profile information. You can view the text right in the console:

go tool pprof --text loopcheck ./cpu_10000_serial_verbose.pprof

...or view it with with a non-graphical graphical mode.

go tool pprof --tree loopcheck ./cpu_10000_serial_verbose.pprof 

The output is at the "function" level. You can tell it to output information at the "line" level if you want to get a better idea where the CPU is spinning.

go tool pprof --tree -lines loopcheck ./cpu_10000_serial_verbose.pprof

And of course there's the awesome PDF output with a graphical view of CPU usage.

go tool pprof --pdf -lines loopcheck ./cpu_10000_serial_verbose.pprof > cpu_10000_serial_verbose.pdf

Maybe you want to track the memory usage. To do that I modified the line added to main():

        // Profiling!

        defer profile.Start(profile.MemProfile).Stop()

Recompile, re-run, and follow the above steps to copy the pprof file and run "go tool pprof...", only against the mem* file instead of cpu*. 

Happy analyzing!

Oh, if you're curious, here's the source code I was using for my test...


  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
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
package main

import (
        "fmt"
        "math/rand"
        "os"
        "strconv"
        "sync"
        "time"
        "github.com/davecheney/profile"
)

var slcTimes []int64
var boolSilent bool

func main() {

        // Profiling!
        defer profile.Start(profile.MemProfile).Stop()

        var intCounter int
        var strCounter string
        var strMode string
        var strChatty string

        if len(os.Args) < 4 {
                fmt.Println("Usage: ./loopcheck <count> <serial|parallel|modulo|massive> <verbose|silent>")
                os.Exit(1)
        }

        strCounter = os.Args[1]
        strMode = os.Args[2]
        strChatty = os.Args[3]

        intCounter, err := strconv.Atoi(strCounter)
        if err != nil {
                fmt.Println("This doesn't appear to be a valid count: " + strCounter)
                os.Exit(1)
        }

        if strMode != "serial" && strMode != "parallel" && strMode != "massive" && strMode != "modulo" {
                fmt.Println("Need a mode as second argument of serial, parallel, massive or modulo, not " + strMode)
                os.Exit(1)
        }

        switch strChatty {
        case "verbose":
                boolSilent = true
        case "silent":
                boolSilent = false
        default:
                fmt.Println("Please set verbose or silent run")
                os.Exit(1)
        }

        // Seed the Random function
        rand.Seed(time.Now().UTC().UnixNano())

        var int64Random int64

        // 604,800 seconds is a week...
        // Fill the slice with values
        for b := 0; b < intCounter; b++ {

                //int64Random = rand.Int63()
                int64Random = int64(rand.Int31())

                slcTimes = append(slcTimes, int64Random)
        }

        if strMode == "serial" {
                for i := range slcTimes {
                        HowMuchTime(i)
                }
        }

        if strMode == "massive" {

                var wg sync.WaitGroup
                wg.Add(len(slcTimes))

                for i := range slcTimes {
                        go HowMuchTimeMassive(&wg, i)
                }

                wg.Wait()

        }

        if strMode == "modulo" {

                for i := range slcTimes {

                        // Set the integers
                        intCenturies := 0
                        intDecades := 0
                        intYears := 0
                        intMonths := 0
                        intWeeks := 0
                        intDays := 0
                        intHours := 0
                        intMinutes := 0

                        // Let's get the time to deletion for each entry
                        int64TimeInSeconds := slcTimes[i]

                        // How many centuries?
                        intCenturies = int(int64TimeInSeconds / 3155692600)
                        int64TimeInSeconds = int64TimeInSeconds % 3155692600

                        // How many decades?
                        intDecades = int(int64TimeInSeconds / 315569260)
                        int64TimeInSeconds = int64TimeInSeconds % 315569260

                        // How many years?
                        intYears = int(int64TimeInSeconds / 31556926)
                        int64TimeInSeconds = int64TimeInSeconds % 31556926

                        // How many months?
                        intMonths = int(int64TimeInSeconds / 2629743)
                        int64TimeInSeconds = int64TimeInSeconds % 2629743

                        // How many weeks?
                        intWeeks = int(int64TimeInSeconds / 604800)
                        int64TimeInSeconds = int64TimeInSeconds % 604800

                        // How many days?
                        intDays = int(int64TimeInSeconds / 86400)
                        int64TimeInSeconds = int64TimeInSeconds % 86400

                        // How many hours?
                        intHours = int(int64TimeInSeconds / 3600)
                        int64TimeInSeconds = int64TimeInSeconds % 3600

                        // How many minutes?
                        intMinutes = int(int64TimeInSeconds / 60)

                        // Convert to strings
                        strCenturies := strconv.Itoa(intCenturies)
                        strDecades := strconv.Itoa(intDecades)
                        strYears := strconv.Itoa(intYears)
                        strMonths := strconv.Itoa(intMonths)
                        strWeeks := strconv.Itoa(intWeeks)
                        strDays := strconv.Itoa(intDays)
                        strHours := strconv.Itoa(intHours)
                        strMinutes := strconv.Itoa(intMinutes)

                        // Formatting
                        strCenturies = strCenturies + " Centuries "
                        strDecades = strDecades + " Decades "
                        strYears = strYears + " Years "
                        strMonths = strMonths + " Months "
                        strWeeks = strWeeks + " Weeks "
                        strDays = strDays + " Days "
                        strHours = strHours + " Hours "
                        strMinutes = strMinutes + " Minutes "

                        strMessages := "From " + strconv.FormatInt(slcTimes[i], 10) + " : " + strCenturies + strDecades + strYears + strMonths + strWeeks + strDays + strHours +
strMinutes

                        if boolSilent != false {
                                fmt.Println("Iteration " + strconv.Itoa(i+1) + " : " + strMessages)
                        }
                }

        }

        if strMode == "parallel" {

                var intMax int = intCounter - 1
                var intTemp int
                var wg sync.WaitGroup
                wg.Add(2)

                intTemp = intCounter / 2
                go HowMuchTimeParallel(&wg, 0, intTemp)
                go HowMuchTimeParallel(&wg, intTemp+1, intMax)

                wg.Wait()
        }
}

func HowMuchTime(i int) {

        var intCenturies int
        var intDecades int
        var intYears int
        var intMonths int
        var intWeeks int
        var intDays int
        var intHours int
        var intMinutes int
        var strMessages string

        // Set the integers
        intCenturies = 0
        intDecades = 0
        intYears = 0
        intMonths = 0
        intWeeks = 0
        intDays = 0
        intHours = 0
        intMinutes = 0

        // Let's get the time to deletion for each entry
        int64TimeInSeconds := slcTimes[i]

        // How many centuries?
        for int64TimeInSeconds >= 3155692600 {
                intCenturies++
                int64TimeInSeconds = int64TimeInSeconds - 3155692600
        }
        // How many decades?
        for int64TimeInSeconds >= 315569260 {
                intDecades++
                int64TimeInSeconds = int64TimeInSeconds - 315569260
        }
        // How many years?
        for int64TimeInSeconds >= 31556926 {
                intYears++
                int64TimeInSeconds = int64TimeInSeconds - 31556926
        }
        // How many months?
        for int64TimeInSeconds >= 2629743 {
                intMonths++
                int64TimeInSeconds = int64TimeInSeconds - 2629743
        }
        // How many weeks?
        for int64TimeInSeconds >= 604800 {
                intWeeks++
                int64TimeInSeconds = int64TimeInSeconds - 604800
        }
        // How many days?
        for int64TimeInSeconds >= 86400 {
                intDays++
                int64TimeInSeconds = int64TimeInSeconds - 86400
        }
        // How many hours?
        for int64TimeInSeconds >= 3600 {
                intHours++
                int64TimeInSeconds = int64TimeInSeconds - 3600
        }
        // How many minutes?
        for int64TimeInSeconds >= 60 {
                intMinutes++
                int64TimeInSeconds = int64TimeInSeconds - 60
        }
        // Convert to strings
        strCenturies := strconv.Itoa(intCenturies)
        strDecades := strconv.Itoa(intDecades)
        strYears := strconv.Itoa(intYears)
        strMonths := strconv.Itoa(intMonths)
        strWeeks := strconv.Itoa(intWeeks)
        strDays := strconv.Itoa(intDays)
        strHours := strconv.Itoa(intHours)
        strMinutes := strconv.Itoa(intMinutes)
        // Formatting
        strCenturies = strCenturies + " Centuries "
        strDecades = strDecades + " Decades "
        strYears = strYears + " Years "
        strMonths = strMonths + " Months "
        strWeeks = strWeeks + " Weeks "
        strDays = strDays + " Days "
        strHours = strHours + " Hours "
        strMinutes = strMinutes + " Minutes "
        strMessages = "From " + strconv.FormatInt(slcTimes[i], 10) + " : " + strCenturies + strDecades + strYears + strMonths + strWeeks + strDays + strHours + strMinutes
        if boolSilent != false {

                fmt.Println("Iteration " + strconv.Itoa(i+1) + " : " + strMessages)
        }
}

func HowMuchTimeMassive(wg *sync.WaitGroup, i int) {

        var intCenturies int
        var intDecades int
        var intYears int
        var intMonths int
        var intWeeks int
        var intDays int
        var intHours int
        var intMinutes int
        var strMessages string

        // Set the integers
        intCenturies = 0
        intDecades = 0
        intYears = 0
        intMonths = 0
        intWeeks = 0
        intDays = 0
        intHours = 0
        intMinutes = 0

        // Let's get the time to deletion for each entry
        int64TimeInSeconds := slcTimes[i]

        // How many centuries?
        for int64TimeInSeconds >= 3155692600 {
                intCenturies++
                int64TimeInSeconds = int64TimeInSeconds - 3155692600
        }
        // How many decades?
        for int64TimeInSeconds >= 315569260 {
                intDecades++
                int64TimeInSeconds = int64TimeInSeconds - 315569260
        }
        // How many years?
        for int64TimeInSeconds >= 31556926 {
                intYears++
                int64TimeInSeconds = int64TimeInSeconds - 31556926
        }
        // How many months?
        for int64TimeInSeconds >= 2629743 {
                intMonths++
                int64TimeInSeconds = int64TimeInSeconds - 2629743
        }
        // How many weeks?
        for int64TimeInSeconds >= 604800 {
                intWeeks++
                int64TimeInSeconds = int64TimeInSeconds - 604800
        }
        // How many days?
        for int64TimeInSeconds >= 86400 {
                intDays++
                int64TimeInSeconds = int64TimeInSeconds - 86400
        }
        // How many hours?
        for int64TimeInSeconds >= 3600 {
                intHours++
                int64TimeInSeconds = int64TimeInSeconds - 3600
        }
        // How many minutes?
        for int64TimeInSeconds >= 60 {
                intMinutes++
                int64TimeInSeconds = int64TimeInSeconds - 60
        }
        // Convert to strings
        strCenturies := strconv.Itoa(intCenturies)
        strDecades := strconv.Itoa(intDecades)
        strYears := strconv.Itoa(intYears)
        strMonths := strconv.Itoa(intMonths)
        strWeeks := strconv.Itoa(intWeeks)
        strDays := strconv.Itoa(intDays)
        strHours := strconv.Itoa(intHours)
        strMinutes := strconv.Itoa(intMinutes)
        // Formatting
        strCenturies = strCenturies + " Centuries "
        strDecades = strDecades + " Decades "
        strYears = strYears + " Years "
        strMonths = strMonths + " Months "
        strWeeks = strWeeks + " Weeks "
        strDays = strDays + " Days "
        strHours = strHours + " Hours "
        strMinutes = strMinutes + " Minutes "
        strMessages = "From " + strconv.FormatInt(slcTimes[i], 10) + " : " + strCenturies + strDecades + strYears + strMonths + strWeeks + strDays + strHours + strMinutes
        if boolSilent != false {
                fmt.Println("Iteration " + strconv.Itoa(i+1) + " : " + strMessages)
        }

        wg.Done()

}

func HowMuchTimeParallel(wg *sync.WaitGroup, min int, max int) {

        var intCenturies int
        var intDecades int
        var intYears int
        var intMonths int
        var intWeeks int
        var intDays int
        var intHours int
        var intMinutes int
        var strMessages string

        // Set the integers
        intCenturies = 0
        intDecades = 0
        intYears = 0
        intMonths = 0
        intWeeks = 0
        intDays = 0
        intHours = 0
        intMinutes = 0

        for i := min; i <= max; i++ {
                // Let's get the time to deletion for each entry
                int64TimeInSeconds := slcTimes[i]

                // How many centuries?
                for int64TimeInSeconds >= 3155692600 {
                        intCenturies++
                        int64TimeInSeconds = int64TimeInSeconds - 3155692600
                }
                // How many decades?
                for int64TimeInSeconds >= 315569260 {
                        intDecades++
                        int64TimeInSeconds = int64TimeInSeconds - 315569260
                }
                // How many years?
                for int64TimeInSeconds >= 31556926 {
                        intYears++
                        int64TimeInSeconds = int64TimeInSeconds - 31556926
                }
                // How many months?
                for int64TimeInSeconds >= 2629743 {
                        intMonths++
                        int64TimeInSeconds = int64TimeInSeconds - 2629743
                }
                // How many weeks?
                for int64TimeInSeconds >= 604800 {
                        intWeeks++
                        int64TimeInSeconds = int64TimeInSeconds - 604800
                }
                // How many days?
                for int64TimeInSeconds >= 86400 {
                        intDays++
                        int64TimeInSeconds = int64TimeInSeconds - 86400
                }
                // How many hours?
                for int64TimeInSeconds >= 3600 {
                        intHours++
                        int64TimeInSeconds = int64TimeInSeconds - 3600
                }
                // How many minutes?
                for int64TimeInSeconds >= 60 {
                        intMinutes++
                        int64TimeInSeconds = int64TimeInSeconds - 60
                }
                // Convert to strings
                strCenturies := strconv.Itoa(intCenturies)
                strDecades := strconv.Itoa(intDecades)
                strYears := strconv.Itoa(intYears)
                strMonths := strconv.Itoa(intMonths)
                strWeeks := strconv.Itoa(intWeeks)
                strDays := strconv.Itoa(intDays)
                strHours := strconv.Itoa(intHours)
                strMinutes := strconv.Itoa(intMinutes)
                // Formatting
                strCenturies = strCenturies + " Centuries "
                strDecades = strDecades + " Decades "
                strYears = strYears + " Years "
                strMonths = strMonths + " Months "
                strWeeks = strWeeks + " Weeks "
                strDays = strDays + " Days "
                strHours = strHours + " Hours "
                strMinutes = strMinutes + " Minutes "
                strMessages = " From " + strconv.FormatInt(slcTimes[i], 10) + " : " + strCenturies + strDecades + strYears + strMonths + strWeeks + strDays + strHours + strMinut
es
                if boolSilent != false {

                        fmt.Println("Iteration " + strconv.Itoa(i+1) + " : " + strMessages)
                }
        }

        wg.Done()
}

No comments:

Post a Comment