Sysadmin Still Surviving: 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...

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()
}

Sysadmin Still Surviving

Tuesday, July 28, 2015

Learning to Profile a Go Application (pprof Fun)

No comments:

Post a Comment