10

I've started to profile some of my Go1.2 code and the top item is always something named 'etext'. I've searched around but couldn't find much information about it other than it might relate to call depth in Go routines. However, I'm not using any Go routines and 'etext' is still taking up 75% or more of the total execution time.

(pprof) top20 
Total: 171 samples
    128  74.9%  74.9%      128  74.9% etext

Can anybody explain what this is and if there is any way to reduce the impact?

Petar Vučetin
  • 3,555
  • 2
  • 22
  • 31
Bill
  • 25,119
  • 8
  • 94
  • 125
  • This seems relevant: https://groups.google.com/d/topic/golang-nuts/KEkZ0-t4Bu0/discussion Apparently it's got something to do with a bug in OSX. – Tyler Jan 23 '14 at 07:39
  • This might also be relevant: http://grokbase.com/t/gg/golang-nuts/13chm1zt6a/go-nuts-a-performance-degradation-with-go-1-2 – Agis Jan 23 '14 at 07:50
  • 2
    Yeah, I found both of those but I'm profiling on Linux so the first article doesn't apply and I'm not using function literals or lots of recursion so I couldn't see how the second would apply. – Bill Jan 23 '14 at 19:06
  • Can you analyze where these calls come from? – Matthias Urlichs Jan 24 '14 at 12:19
  • @Matthias How would I do that? – Bill Jan 24 '14 at 21:30
  • etext is a symbol that marks the end of the text segment. That looks like a bug to me. Do you dynamically load libraries in your code? – fuz Jan 25 '14 at 17:55
  • No, it's pretty straight forward Go. – Bill Jan 25 '14 at 19:18
  • 1
    While etext is beyond the normal text segment, shared libraries are mapped beyond that, so it might be a shared lib without symbols (on Debian, for instance, you have to specifically install the -dbg packages). Or it might be a trampoline call, i.e. a short code snippet built at runtime. – Matthias Urlichs Jan 25 '14 at 19:55
  • I'm on Ubuntu - what should I do to troubleshoot? Do I need to install something else? Also is it just a problem with profiling, or once fixed will the code run faster? – Bill Jan 25 '14 at 21:03

2 Answers2

3

I hit the same problem then I found this: pprof broken in go 1.2?. To verify that it is really a 1.2 bug I wrote the following "hello world" program:

package main

import (
    "fmt"
    "testing"
)

func BenchmarkPrintln( t *testing.B ){
    TestPrintln( nil )
}

func TestPrintln( t *testing.T ){
    for i := 0; i < 10000; i++ {
            fmt.Println("hello " + " world!")
    }
}

As you can see it only calls fmt.Println.

You can compile this with “go test –c .” Run with “./test.test -test.bench . -test.cpuprofile=test.prof” See the result with “go tool pprof test.test test.prof”

(pprof) top10
Total: 36 samples
  18  50.0%  50.0%       18  50.0% syscall.Syscall
   8  22.2%  72.2%        8  22.2% etext
   4  11.1%  83.3%        4  11.1% runtime.usleep
   3   8.3%  91.7%        3   8.3% runtime.futex
   1   2.8%  94.4%        1   2.8% MHeap_AllocLocked
   1   2.8%  97.2%        1   2.8% fmt.(*fmt).padString
   1   2.8% 100.0%        1   2.8% os.epipecheck
   0   0.0% 100.0%        1   2.8% MCentral_Grow
   0   0.0% 100.0%       33  91.7% System
   0   0.0% 100.0%        3   8.3% _/home/xxiao/work/test.BenchmarkPrintln

The above result is got using go 1.2.1 Then I did the same thing using go 1.1.1 and got the following result:

(pprof) top10
Total: 10 samples
   2  20.0%  20.0%        2  20.0% scanblock
   1  10.0%  30.0%        1  10.0% fmt.(*pp).free
   1  10.0%  40.0%        1  10.0% fmt.(*pp).printField
   1  10.0%  50.0%        2  20.0% fmt.newPrinter
   1  10.0%  60.0%        2  20.0% os.(*File).Write
   1  10.0%  70.0%        1  10.0% runtime.MCache_Alloc
   1  10.0%  80.0%        1  10.0% runtime.exitsyscall
   1  10.0%  90.0%        1  10.0% sweepspan
   1  10.0% 100.0%        1  10.0% sync.(*Mutex).Lock
   0   0.0% 100.0%        6  60.0% _/home/xxiao/work/test.BenchmarkPrintln

You can see that the 1.2.1 result does not make much sense. Syscall and etext takes most of the time. And the 1.1.1 result looks right.

So I'm convinced that it is really a 1.2.1 bug. And I switched to use go 1.1.1 in my real project and I'm satisfied with the profiling result now.

Xipan Xiao
  • 343
  • 1
  • 10
2

I think Mathias Urlichs is right regarding missing debugging symbols in your cgo code. Its worth noting that some standard pkgs like net and syscall make use of cgo.

If you scroll down to the bottom of this doc to the section called Caveats, you can see that the third bullet says...

If the program linked in a library that was not compiled with enough symbolic information, all samples associated with the library may be charged to the last symbol found in the program before the library. This will artificially inflate the count for that symbol.

I'm not 100% positive this is what's happening but i'm betting that this is why etext appears to be so busy (in other words etext is a collection of various functions that doesn't have enough information for pprof to analysis properly.).

mortdeus
  • 197
  • 2