pkg / profile Goto Github PK

I've tried to avoid this for now, but it's time to add tests. The basic idea is to create a helper function

// runTest executes the go program supplied and returns the contents of stdout, stderr, and an error which may contain status information about the result of the program.
func runTest(code string) (stdout []byte, stderr []byte, err error)

I'll take adding this testing framework.

I have been trying to collect CPU and Memory profiles for a program I wrote.
I have imported "github.com/pkg/profile" and added the appropriate line for either CPU or Memory profile.

import (
    ...
    "github.com/pkg/profile"
    ...
)

...

func main() {
    // memory profile
    defer profile.Start(profile.MemProfile, profile.ProfilePath("./profiles/")).Stop()
    // OR cpu profile
    defer profile.Start(profile.CPUProfile, profile.ProfilePath("./profiles/")).Stop()
}

When I run the program, I see messages like the following on the command line:

2019/10/11 12:33:24 profile: memory profiling enabled (rate 4096), profiles/mem.pprof

However, the cpu.pprof or mem.pprof files are always 0 bytes. This used to work before for the same program, I do not understand why this no longer works.

ls -alhrt profiles
total 8.0K
-rw-rw-r-- 1 manas manas    0 Oct 11 12:33 mem.pprof
drwxrwxr-x 9 manas manas 4.0K Oct 11 12:33 ..
drwxrwxr-x 2 manas manas 4.0K Oct 11 12:33 .

Hi,

During packaging this project for Guix I've found that unit tests are failing:

--- FAIL: TestProfile (5.32s)
    profile_test.go:216: default profile (cpu)
    profile_test.go:216: memory profile
    profile_test.go:216: memory profile (rate 2048)
    profile_test.go:216: double start
    profile_test.go:216: block profile
    profile_test.go:216: mutex profile
    profile_test.go:216: clock profile
    profile_test.go:258: error: expected nil, got exit status 1
    profile_test.go:216: profile path
    profile_test.go:216: profile path error
    profile_test.go:216: multiple profile sessions
    profile_test.go:216: profile quiet
FAIL
FAIL    github.com/pkg/profile  5.318s
FAIL

Version: v1.7.0

List of all imputs:

• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• go-github-com-ianlancetaylor-demangle@0.0.0-20230524184225-eabc099b10ab
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]
• [email protected]

Every time I use this package, I think that I can do something like:

var flagCPUProfile = flag.String("cpuprofile", "", "write a cpuprofile to `cpuprofile`")

func main() {
	if *flagCPUProfile != "" {
		defer profile.Start(profile.ProfilePath(*flagCPUProfile)).Stop()
	}

And then I run the program with -cpuprofile=somename.pprof. And there is no profile to be found.

And then I dig through the docs and discover ProfilePath is supposed to be a directory. And then I wish there was a way to provide a filename. This is because I sometimes do multiple runs, and I want to write the results to different profiles so that I can combine them, and I don't want to have to deal with creating and cleaning up a directory per profile.

May I send a PR to add ProfileFilename, or something like it?

This is a tracking issue for releasing version 1.0.0.

The API of this package has been stable for more than a year now so it's time to put a 1.0.0 release on it and call it a day.

getting this error while running go tool pprof -text ./jiva

failed to fetch any source profiles

binary build on go version 1.7.3 testing on go version 1.10

After profiling I get a 10 byte file (cpu.pprof.zip) that when read produces:

• cpu.pprof: decompressing profile: unexpected EOF ( With go tool pprof cpu.pprof)
• Unexpected end of ZLIB input stream (With Goland)

Tried both:

defer profile.Start(profile.ProfilePath(os.Getenv("HOME"))).Stop()

as well as:

p := profile.Start(profile.ProfilePath(os.Getenv("HOME")), profile.NoShutdownHook)
// ...
p.Stop()

As of 3704c8d on macOS Big Sur 11.1.

With the shutdown hook I saw the library was intercepting shutdown to stop profiling. Without it I see my code called to .Stop().

Troubleshooting ideas?

Thanks for your work.

Hi. I hope everyone is having a great new year so far.

I was told by a colleague I could use this package for determining how much time is being spent in each function during an application's run. Is this correct and, if so, how? I saw nothing in the documentation which makes this clear if so.

Thanks in advance.

Commit 3704c8d changed the signatures of MemProfile{Heap,Allocs}. Is this going to require a v2?

I would like to profile both heap and cpu at the same time. It seems to be possible (although i have not tried) with runtime/pprof package API. I have tried profile.Start(opt, profile.CPUProfile, profile.MemProfile), that only produced mem.pprof file. Quick scan of the code (switch statement) makes me think it is not possible

Failed to remove the files created by the profile pkg
"error":"remove mem.pprof: The process cannot access the file because it is being used by another process."

Running as shown in the example (i.e., defer profile.Start().Stop()) causes a data race:

eric@archbox /tmp $ cat main.go 
package main

import (
    "time"

    "github.com/pkg/profile"
)

func main() {
    defer profile.Start().Stop()
    time.Sleep(5 * time.Second)
}
eric@archbox /tmp $ go build -race main.go
eric@archbox /tmp $ ./main 
2016/03/14 14:53:07 profile: cpu profiling enabled, /tmp/profile342323605/cpu.pprof
^C2016/03/14 14:53:08 profile: caught interrupt, stopping profiles
==================
WARNING: DATA RACE
Read by goroutine 8:
  github.com/pkg/profile.(*profile).Stop()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:93 +0x37
  github.com/pkg/profile.Start.func5()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:181 +0x20c

Previous write by main goroutine:
  github.com/pkg/profile.Start()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:187 +0xb22
  main.main()
      /tmp/main.go:10 +0x39

Goroutine 8 (running) created at:
  github.com/pkg/profile.Start()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:184 +0xa14
  main.main()
      /tmp/main.go:10 +0x39
==================
==================
WARNING: DATA RACE
Read by goroutine 8:
  github.com/pkg/profile.(*profile).Stop()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:93 +0x84
  github.com/pkg/profile.Start.func5()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:181 +0x20c

Previous write by main goroutine:
  github.com/pkg/profile.Start()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:189 +0xae3
  main.main()
      /tmp/main.go:10 +0x39

Goroutine 8 (running) created at:
  github.com/pkg/profile.Start()
      /home/eric/gopath/src/github.com/pkg/profile/profile.go:184 +0xa14
  main.main()
      /tmp/main.go:10 +0x39
==================
Found 2 data race(s)

For programs that have both non-trivial shutdown hook plumbing and flags controlling profiling, it'd be convenient to have a NoProfile option with a no-op Stop function. I'll send a PR if you're amenable.

Hi, I'm trying to profile my application using your package following the documentation.
I have a cpu.pprof non empty file generated but pprof is unable to read it

$ go tool pprof —pdf ./app /var/folders/x7/wnp2zjn563j2dr45dsfpvdz80000gn/T/profile464041113/cpu.pprof > out.pdf              nsitbon@mac-ns
parsing profile: unrecognized profile format

I've tried multiple configuration from the default one
defer profile.Start().Stop()
to a more elaborated
defer profile.Start(profile.BlockProfile, profile.MemProfile, profile.CPUProfile).Stop()
but pprof is still unable to parse it.
Any ideas?

FYI

$ go version                                                                                                                  
go version go1.8.3 darwin/amd64

Thanks

Now that we've made it impossible to activate more than one profile at a time, users may attempt to work around this with something like

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

We should decide to support this, and if so, make sure that we move anything which is shared across profiles into the *Profile, see #5. Or, we should prohibit it with some package global lock.

Hello!

I am going to use profile package to find places to optimize my project.
I have followed description and used just defer profile.Start().Stop() with import to run the profiler.
The problem is I always get this error: parsing profile: unrecognized profile format.
I tried to run the application with these commands:

go tool pprof —text ./myapp ./pro/cpu.pprof > prof.txt

go tool pprof —pdf ./myapp

What I did wrong? An application is simple as abc: it is little microservice which uses http package and runs cmd tool to get its output.

Thank you in advance.

In the readme, there is an example which is shows how to use profile.MemProfileAllocs in the Start function, but the sample is wrong and you'll get an error like

cannot use profile.MemProfileAllocs (type func() func(*profile.Profile)) as type func(*profile.Profile) in argument to profile.Start

And the readme should be
p := profile.Start(profile.MemProfileAllocs(), profile.ProfilePath("."), profile.NoShutdownHook)

So if do you confirm it's wrong can I send a PR to fix the readme or the codebase?

I'm writing a web app and using /wg/wrk to stress test it along with this tool but don't understand the output. Here's the CPU profile output after running wrk -t12 -c400 -d7s http://127.0.0.1:8080

Hi,

I have a use case where I want to trigger profiles on a remote server and then load the resulting file via an HTTP endpoint. It seemed to me supporting writing the raw bytes to an arbitrary io.Writer would be the most generic way of supporting that use case (and potentially others).

I have a fork with code that works for me on master at https://github.com/VerizonDigital/profile, but it's kind of messy feeling and doesn't have any new tests for the io.Writer portion. Is this something you're interested in? I'm more than happy to change the way I've implemented it if you have any changes you'd like made.

Thanks for the work you've done so far. Starting with this made my life easier. :D

Fantastic tool.

One thing, say I have a binary that is loading slowly from a massive amount of imports that may possibly be having side effects upon code being loaded.

I don't see how to use profile here because I put defer profile.Start().Stop() at the beginning of main but that doesn't capture the loading/code execution of library code.

thank you

https://github.com/bluesea147/6.824

I tried using the package to profile this project. It cannot build the binary needed for the pprof.

Is it one of the designed use cases of this package?

One of the ways to run this project is to :
export GOPATH=/home/XXX/6.824
go get github.com/pkg/profile
go test -run Sequential

I'm trying to profile a simple application:

package main

import (
    "github.com/pkg/profile"
    "github.com/spf13/cobra"
    "strings"
)

/*
Tokenize TODO
*/
func Tokenize(text string) []string {
    return strings.Split(text, "\n")
}

func main() {
    profileCommand := &cobra.Command{
        Use: "profile",
        Run: func(cmd *cobra.Command, args []string) {
            defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop()

            Tokenize("Hello\nWorld")
        },
    }

    rootCommand := &cobra.Command{Use: "bern"}
    rootCommand.AddCommand(profileCommand)
    rootCommand.Execute()
}

But when I look at the cpu.pprof file it simply contains ' and nothing else.
What am I doing incorrectly?

This was a very nice package I've only been waiting to use...

For a potential v2, I suggest reducing the stutter in the API (as also mentioned in this comment):

profile.Path
profile.CPU
profile.Mem
profile.Allocs
...

I've written a program that reads a csv (2.1m records) and builds sql insert statements into mariadb instance. It takes about 7minutes to complete the cpu level on my macbook pro (sierra) go to about 65% and the activity monitor shows upwards of 1GB to even 3.7 GB sometimes. I added the profiler to my project and tried to analyze the results but it seems to show that the program used about 25MB. I'm not sure what to read from this. here is a contrived version of my code and some pictures of the activity monitor.

func main(){
    //Setup and Connect to database 
    //Set variables
    //Read CSV File
    dbConnect()
    defer db.Close()
    db.DB().SetMaxOpenConns(90)
    db.DB().SetMaxIdleConns(10)
    db.DB().SetConnMaxLifetime(time.Second * 14400)
    filehandle, err := os.Open(physicianCSV)
    checkErr(err)
    defer filehandle.Close()

    reader := csv.NewReader(filehandle)
    _, err = reader.Read()
    checkErr(err)

    for i := 0; i <= readLimit; i++ {
        record, err := reader.Read()
        if err != nil {
            if err == io.EOF {
                break
            }
            panic(err)
        }
        physician = convertCSVRecordToPhysician(record)
        //..Do stuff with physician, edit object properties via pointer

        physicians = append(physicians, physician)

        if math.Mod(float64(i), float64(bulkAmount)) == 0 && i != 0 {
            fmt.Println(i, "Records: From ", i-bulkAmount, "to", i)
            wg.Add(1)
            sliceOfPhys := make([]Physician, bulkAmount)
            copy(sliceOfPhys, physicians)
            go bulkSavePhysicians(sliceOfPhys)
            physicians = physicians[:0]

        }
    }

    fmt.Println(readLimit, "records inserted")
    wg.Wait()
}

func bulkSavePhysicians(_physicians []Physician) {
    defer func() {
        if x := recover(); x != nil {
            fmt.Println(x)
        }
    }()
    defer wg.Done()

    sqlStringArray := buildSQLStatements(_physicians)
    batchSQL := fmt.Sprintf("insert into physicians values %s ;", strings.Join(sqlStringArray, ","))
    tx := db.Begin()
    errors := tx.Exec(batchSQL).GetErrors()
    if len(errors) > 0 {
        panic(errors)
    }
    tx.Commit()
}

func buildSQLStatements(_physicians []Physician) []string {

    var valueStr string
    var valueArr []string
    for _, phys := range _physicians {

        valueStr = fmt.Sprintf(`( "%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s","%s" )`, phys.NPI,
            phys.PACID,
            phys.ProfessionalEnrollmentID,
            strings.Replace(phys.LastName, "'", "\\'", -1),
            phys.FirstName,
            phys.MiddleName,
            phys.Suffix,
            phys.Gender,
            phys.Credential,
            strings.Replace(phys.MedicalSchoolName, "'", "\\'", -1),
            phys.GraduationYear,
            phys.PrimarySpecialty,
            phys.SecondarySpecialty1,
            phys.SecondarySpecialty2,
            phys.SecondarySpecialty3,
            phys.SecondarySpecialty4,
            phys.AllSecondarySpecialties,
            strings.Replace(phys.OrganizationLegalName, "'", "\\'", -1),
            phys.GroupPracticePACID,
            phys.NumberOfGroupPracticeMembers,
            strings.Replace(phys.Line1StreetAddress, "'", "\\'", -1),
            phys.Line2StreetAddress,
            phys.MarkerOfAddressLine2Suppression,
            phys.City,
            phys.State,
            phys.ZipCode,
            phys.PhoneNumber,
            phys.HospitalAffiliationCCN1,
            phys.HospitalAffiliationLBN1,
            phys.HospitalAffiliationCCN2,
            phys.HospitalAffiliationLBN2,
            phys.HospitalAffiliationCCN3,
            phys.HospitalAffiliationLBN3,
            phys.HospitalAffiliationCCN4,
            phys.HospitalAffiliationLBN4,
            phys.HospitalAffiliationCCN5,
            phys.HospitalAffiliationLBN5,
            phys.ProfessionalAcceptsMedicareAssignment,
            phys.ReportedQualityMeasures,
            phys.UsedElectronicHealthRecords,
            phys.ParticipatedInTheMedicareMaintenance,
            phys.CommittedToHeartHealth,
            phys.SpecialtyID)

        valueArr = append(valueArr, valueStr)
    }
    return valueArr
}

Here is zip of mem.pprof and cpu.pprof
proffs.zip

An image of activity monitor taken without the profiler inclusion.

I watched your talk and you mentioned that heapSys is the correct value to indicate the amount of memory used in bytes. Am I correct in saying this?
203751424 bytes = 203MB
Calling web from go tool pprof mem.pprof renders the following

I'm confused as to which values to trust.

Problem

Currently the signature of the Start function is

func Start(options ...func(*Profile)) interface {
	Stop()
} 

Use case

The lifecycle in our case is managed by another library (fluent-bit-go)

• The Start() has to happen in lifecycle function FLBPluginInit
• The Stop() has to happen in lifecycle function FLBPluginExit

Proposal

have a named interface for Stop

type Stopper interface {
	Stop()
} 

So the Start will become

func Start(options ...func(*Profile)) Stopper

profile.Start(profile.MemProfile, profile.ProfilePath("."), profile.NoShutdownHook)
profile.Start(profile.CPUProfile, profile.ProfilePath("."), profile.NoShutdownHook)

Starting multiple profiles throws an error : profile: Start() already called

Problem Statement

From my viewpoint, the biggest thing stopping me from using github.com/pkg/profile is its hard stance on "no more than one kind of profiling at a time". Especially since my usual starting assumption is "show me both a CPU profile and a memory (allocs) profile".

Taking a CPU + memory profile, or a CPU + memory + goroutines + mutexes profile is actually quite a sane thing to do in my viewpoint. Further I do sometimes want to get both a trace and a cpu profile from the same long-running program, rather than go to all the trouble of running it twice.

So with that introduction, let me lay out my understanding of why this is an okay thing to do (conversely, why the restriction on "one at a time" is actually necessary and overly restrictive).

Kinds of Profiling

For the sake of my argument I'm going to focus primarily on the distinction between active and passive profiles.

There are two kinds of active profiles: CPU profiling and execution tracing. Here the cost of instrumentation is so high that they only run for a set amount of time (say take a 10-second CPU profile from a server, or re-running a tool with trace profiling turned on for the duration).

On the other hand there are passive profiles including allocs, block, goroutine, heap, mutex, and threadcreate. Here the instrumentation cost is low enough that these profiles are latently always on; their counts are collected all the time, and can be collected at any point in time.

NOTE this model is of course complicated by the fact that there is a tuning knob for the passive/always-on memory profiler, which pkg/profile is fairly unique in making such a user-facing API-out of (to say nothing of the basically unusable CPU profiler hz tuning knob...)

Common Combinations

Of all those lovely modes of profiling CPU, memory, and tracing are the most generally known, used, and useful; as evidenced by the prevalent flag idioms -cpuprofile FILE, -memprofile FILE, and -trace FILE.

There's really no problem in combining CPU profiling and memory profiling (at normal rates); to the contrary: since the memory profiler is always on any how, you may as well dump it at the end (in the context of an offline tool, which seems to be the use-case that pkg/profile is most suited for). The same goes for any/all of the other passive profilers: they already have their counts just sitting there, you're only doing yourself a harm by not dumping the data.

The most concern comes when combining CPU profiling and tracing. But even there, at least in my experience, any cross-chatter is fairly easy to pick out or compensate for:

• in the event trace, you can at least see that a CPU profile was going on, since there will be at least one dedicated goroutine writing it out over some time span (you should even be able to see the os-interrupt timing... but I've not actually tried to do that, and now I'm purely speculating in parenthetical...)
• there is real concern when it comes to skewing the CPU profile however, since every trace instrumentation branch is now hot, further inflating (the probably already dominant) impact of runtime functions
• in practice, for online servers, I always sequence tracing and CPU profiling for this reason, rather than do them in parallel; however for an offline tool where your profiling its entire lifecycle, there are times when you want to see both concurrently (even if you also re-run it to also get a "pure" trace and cpu profile)

Why I Care

In my view pkg/profile is very close to fully solving the use case of "lifetime profiling for an offline tool / batch task". I'd like to wrap some flag.Value implementation around it and use it as a dependency (maybe even send a pull request for adding the flag convenience).

However in its current form, not being able to take several at once is a bit of a blocker for that use case.

I'm trying to create a Debian package for profile. The test TestProfile fails during the build of the packages:

go test -v -p 4 github.com/pkg/profile
=== RUN   TestProfile
--- FAIL: TestProfile (1.75s)
profile_test.go:174: default profile (cpu)
profile_test.go:174: memory profile
profile_test.go:174: memory profile (rate 2048)
profile_test.go:174: double start
profile_test.go:174: block profile
profile_test.go:174: profile path
profile_test.go:174: profile path error
profile_test.go:194: stderr: wanted '[could not create initial output]', got '2017/05/09 06:50:47 profile: cpu profiling enabled, README.md/cpu.pprof
	2017/05/09 06:50:47 profile: cpu profiling disabled, README.md/cpu.pprof
	'
profile_test.go:209: expected error
profile_test.go:174: multiple profile sessions
profile_test.go:174: profile quiet

Hi Dave,

Just throwing this out there. How would you feel about command-line flags?

I'm thinking of situations where you (have a binary or) want to run a different kind of profile and it would be more convenient to just add a flag rather than re-editing the source. Do you think that would be useful?

🎁

With the switch over to pkg/profile the library now does not allow intermediate handling of configuration objects.

Previously I could assemble configuration settings and pass them onto Start, eg:
(in psuedocode)

    variable profiling options
    switch (command line profiling type option) {
        assign profiling type to profiling options
    }
    if (provided output destination) {
        assign specified destination to profiling options
    }
    ....Start(profiling options)

Now that the profile object is not exporting I am unclear how to code this same setup in a way that doesn't reek of poor code re-duplication RE: the Start call:

func StartWithDestination(profileType ProfileType, toOutputFolder string) interface {
    Stop()
} {

    switch profileType {
    case CPU:
        return profile.Start(profile.CPUProfile, profile.ProfilePath(toOutputFolder))

    case Memory:
        return profile.Start(profile.MemProfile, profile.ProfilePath(toOutputFolder))

    case Blocking:
        return profile.Start(profile.BlockProfile, profile.ProfilePath(toOutputFolder))
    }

    return nil
}

func Start(profileType ProfileType) interface {
    Stop()
} {
    switch profileType {
    case CPU:
        return profile.Start(profile.CPUProfile)

    case Memory:
        return profile.Start(profile.MemProfile)

    case Blocking:
        return profile.Start(profile.BlockProfile)
    }

    return nil
}

...

if len(toOutputFolder) > 0 {
    return profiler.StartWithDestination(profileType, toOutputFolder)
}
return profiler.Start(profileType)

Is there a way I can be smarter with the new library?