wolfstudy commented on issue #195: perf tools performance about 1/10 of java client URL: https://github.com/apache/pulsar-client-go/issues/195#issuecomment-600416600 ``` (pprof) tree Showing nodes accounting for 73.60s, 93.73% of 78.52s total Dropped 257 nodes (cum <= 0.39s) Showing top 80 nodes out of 91 ----------------------------------------------------------+------------- flat flat% sum% cum cum% calls calls% + context ----------------------------------------------------------+------------- 19.75s 100% | runtime.semasleep 19.75s 25.15% 25.15% 19.75s 25.15% | runtime.pthread_cond_wait ----------------------------------------------------------+------------- 14.72s 99.80% | runtime.notewakeup 14.75s 18.79% 43.94% 14.75s 18.79% | runtime.pthread_cond_signal ----------------------------------------------------------+------------- 8.68s 72.76% | internal/poll.(*FD).Write 3.25s 27.24% | internal/poll.(*FD).Read 11.23s 14.30% 58.24% 11.93s 15.19% | syscall.syscall 0.67s 5.62% | runtime.exitsyscall ----------------------------------------------------------+------------- 9.11s 100% | runtime.netpoll 9.10s 11.59% 69.83% 9.11s 11.60% | runtime.kevent ----------------------------------------------------------+------------- 4.41s 79.75% | runtime.runqgrab 0.90s 16.27% | runtime.mstart1 0.21s 3.80% | runtime.lock 5.53s 7.04% 76.87% 5.53s 7.04% | runtime.usleep ----------------------------------------------------------+------------- 4.61s 99.78% | runtime.gcDrain 2.70s 3.44% 80.31% 4.62s 5.88% | runtime.scanobject 1.13s 24.46% | runtime.findObject 0.58s 12.55% | runtime.greyobject ----------------------------------------------------------+------------- 0.87s 44.62% | runtime.findrunnable 0.85s 43.59% | runtime.mstart1 0.15s 7.69% | runtime.notetsleep_internal 1.94s 2.47% 82.78% 1.95s 2.48% | runtime.nanotime ----------------------------------------------------------+------------- 1.15s 1.46% 84.25% 3.01s 3.83% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).runEventsLoop 1.67s 55.48% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalSend 0.17s 5.65% | runtime.selectgo ----------------------------------------------------------+------------- 0.97s 85.84% | runtime.mallocgc 0.13s 11.50% | runtime.(*mcentral).cacheSpan 1.13s 1.44% 85.69% 1.13s 1.44% | runtime.memclrNoHeapPointers ----------------------------------------------------------+------------- 1.13s 93.39% | runtime.scanobject 0.99s 1.26% 86.95% 1.21s 1.54% | runtime.findObject ----------------------------------------------------------+------------- 0.90s 100% | runtime.selectgo 0.90s 1.15% 88.09% 0.90s 1.15% | runtime.(*waitq).dequeueSudoG ----------------------------------------------------------+------------- 9.83s 98.60% | runtime.findrunnable 0.13s 1.30% | runtime.gcDrain 0.83s 1.06% 89.15% 9.97s 12.70% | runtime.netpoll 9.11s 91.37% | runtime.kevent ----------------------------------------------------------+------------- 0.66s 100% | runtime.exitsyscall 0.62s 0.79% 89.94% 0.66s 0.84% | runtime.exitsyscallfast ----------------------------------------------------------+------------- 0.61s 100% | github.com/golang/protobuf/proto.Unmarshal 0.57s 0.73% 90.66% 0.61s 0.78% | github.com/apache/pulsar-client-go/pulsar/internal/pb.(*BaseCommand).Reset ----------------------------------------------------------+------------- 5.61s 100% | runtime.gcBgMarkWorker.func2 0.49s 0.62% 91.29% 5.61s 7.14% | runtime.gcDrain 4.61s 82.17% | runtime.scanobject 0.13s 2.32% | runtime.netpoll ----------------------------------------------------------+------------- 0.48s 100% | runtime.semasleep 0.48s 0.61% 91.90% 0.48s 0.61% | runtime.pthread_cond_timedwait_relative_np ----------------------------------------------------------+------------- 1.23s 66.85% | runtime.newobject 0.45s 24.46% | runtime.makeslice 0.18s 0.23% 92.13% 1.84s 2.34% | runtime.mallocgc 0.97s 52.72% | runtime.memclrNoHeapPointers 0.46s 25.00% | runtime.(*mcache).nextFree ----------------------------------------------------------+------------- 0.39s 86.67% | runtime.mstart1 0.18s 0.23% 92.36% 0.45s 0.57% | runtime.notetsleep 0.27s 60.00% | runtime.notetsleep_internal ----------------------------------------------------------+------------- 3.42s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readAtLeast 0.12s 0.15% 92.51% 3.42s 4.36% | io.ReadAtLeast 3.30s 96.49% | net.(*conn).Read ----------------------------------------------------------+------------- 35.46s 100% | runtime.schedule 0.12s 0.15% 92.66% 35.46s 45.16% | runtime.findrunnable 19.81s 55.87% | runtime.stopm 9.83s 27.72% | runtime.netpoll 4.56s 12.86% | runtime.runqsteal 0.87s 2.45% | runtime.nanotime ----------------------------------------------------------+------------- 0.12s 0.15% 92.82% 0.42s 0.53% | runtime.lock 0.21s 50.00% | runtime.usleep ----------------------------------------------------------+------------- 0.97s 100% | main.newProducerCommand.func1 0.10s 0.13% 92.94% 0.97s 1.24% | main.produce 0.80s 82.47% | runtime.selectgo ----------------------------------------------------------+------------- 4.52s 100% | runtime.runqsteal 0.10s 0.13% 93.07% 4.52s 5.76% | runtime.runqgrab 4.41s 97.57% | runtime.usleep ----------------------------------------------------------+------------- 0.58s 98.31% | runtime.scanobject 0.08s 0.1% 93.17% 0.59s 0.75% | runtime.greyobject ----------------------------------------------------------+------------- 1.09s 100% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalFlushCurrentBatch 0.04s 0.051% 93.22% 1.09s 1.39% | github.com/apache/pulsar-client-go/pulsar/internal.(*BatchBuilder).Flush 0.62s 56.88% | github.com/apache/pulsar-client-go/pulsar/internal.serializeBatch 0.33s 30.28% | runtime.makeslice ----------------------------------------------------------+------------- 4.56s 100% | runtime.findrunnable 0.04s 0.051% 93.28% 4.56s 5.81% | runtime.runqsteal 4.52s 99.12% | runtime.runqgrab ----------------------------------------------------------+------------- 0.80s 69.57% | main.produce 0.18s 15.65% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run 0.17s 14.78% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).runEventsLoop 0.04s 0.051% 93.33% 1.15s 1.46% | runtime.selectgo 0.90s 78.26% | runtime.(*waitq).dequeueSudoG ----------------------------------------------------------+------------- 1.28s 99.22% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalSend 0.03s 0.038% 93.36% 1.29s 1.64% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalFlushCurrentBatch 1.09s 84.50% | github.com/apache/pulsar-client-go/pulsar/internal.(*BatchBuilder).Flush ----------------------------------------------------------+------------- 1.67s 100% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).runEventsLoop 0.03s 0.038% 93.40% 1.67s 2.13% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalSend 1.28s 76.65% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalFlushCurrentBatch 0.13s 7.78% | github.com/golang/protobuf/proto.Marshal 0.08s 4.79% | runtime.newobject ----------------------------------------------------------+------------- 0.87s 69.05% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).SendAsync 0.09s 7.14% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).deserializeCmd 0.08s 6.35% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalSend 0.03s 0.038% 93.44% 1.26s 1.60% | runtime.newobject 1.23s 97.62% | runtime.mallocgc ----------------------------------------------------------+------------- 8.79s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run 0.02s 0.025% 93.47% 8.79s 11.19% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).internalWriteData 8.74s 99.43% | net.(*conn).Write ----------------------------------------------------------+------------- 0.02s 0.025% 93.49% 4.45s 5.67% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readFromConnection 4.35s 97.75% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readSingleCommand ----------------------------------------------------------+------------- 4.35s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readFromConnection 0.02s 0.025% 93.52% 4.35s 5.54% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readSingleCommand 3.42s 78.62% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readAtLeast 0.91s 20.92% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).deserializeCmd ----------------------------------------------------------+------------- 0.41s 75.93% | github.com/apache/pulsar-client-go/pulsar/internal.serializeBatch 0.13s 24.07% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).internalSend 0.02s 0.025% 93.54% 0.54s 0.69% | github.com/golang/protobuf/proto.Marshal 0.12s 22.22% | runtime.makeslice ----------------------------------------------------------+------------- 0.46s 100% | runtime.(*mcache).refill 0.02s 0.025% 93.57% 0.46s 0.59% | runtime.(*mcentral).cacheSpan 0.14s 30.43% | runtime.systemstack 0.13s 28.26% | runtime.memclrNoHeapPointers ----------------------------------------------------------+------------- 37.43s 98.50% | runtime.park_m 0.56s 1.47% | runtime.goschedImpl 0.02s 0.025% 93.59% 38s 48.40% | runtime.schedule 35.46s 93.32% | runtime.findrunnable 2.48s 6.53% | runtime.notewakeup ----------------------------------------------------------+------------- 19.78s 97.53% | runtime.notesleep 0.49s 2.42% | runtime.notetsleep_internal 0.02s 0.025% 93.62% 20.28s 25.83% | runtime.semasleep 19.75s 97.39% | runtime.pthread_cond_wait 0.48s 2.37% | runtime.pthread_cond_timedwait_relative_np ----------------------------------------------------------+------------- 0.82s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).deserializeCmd 0.01s 0.013% 93.63% 0.82s 1.04% | github.com/golang/protobuf/proto.Unmarshal 0.61s 74.39% | github.com/apache/pulsar-client-go/pulsar/internal/pb.(*BaseCommand).Reset ----------------------------------------------------------+------------- 8.74s 100% | net.(*netFD).Write 0.01s 0.013% 93.64% 8.74s 11.13% | internal/poll.(*FD).Write 8.68s 99.31% | syscall.syscall ----------------------------------------------------------+------------- 3.30s 100% | net.(*conn).Read 0.01s 0.013% 93.66% 3.30s 4.20% | net.(*netFD).Read 3.29s 99.70% | internal/poll.(*FD).Read ----------------------------------------------------------+------------- 0.67s 100% | syscall.syscall 0.01s 0.013% 93.67% 0.67s 0.85% | runtime.exitsyscall 0.66s 98.51% | runtime.exitsyscallfast ----------------------------------------------------------+------------- 0.62s 100% | runtime.mcall 0.01s 0.013% 93.68% 0.62s 0.79% | runtime.gosched_m 0.61s 98.39% | runtime.goschedImpl ----------------------------------------------------------+------------- 0.01s 0.013% 93.70% 38.09s 48.51% | runtime.mcall 37.43s 98.27% | runtime.park_m 0.62s 1.63% | runtime.gosched_m ----------------------------------------------------------+------------- 19.79s 100% | runtime.stopm 0.01s 0.013% 93.71% 19.79s 25.20% | runtime.notesleep 19.78s 99.95% | runtime.semasleep ----------------------------------------------------------+------------- 19.81s 99.90% | runtime.findrunnable 0.01s 0.013% 93.72% 19.83s 25.25% | runtime.stopm 19.79s 99.80% | runtime.notesleep ----------------------------------------------------------+------------- 12.97s 68.66% | runtime.mstart 5.46s 28.90% | runtime.gcBgMarkWorker 0.14s 0.74% | runtime.(*mcentral).cacheSpan 0.01s 0.013% 93.73% 18.89s 24.06% | runtime.systemstack 6.61s 34.99% | runtime.entersyscallblock_handoff 5.61s 29.70% | runtime.gcBgMarkWorker.func2 5.58s 29.54% | runtime.goready.func1 0.57s 3.02% | runtime.exitsyscallfast.func1 ----------------------------------------------------------+------------- 0.97s 100% | github.com/apache/pulsar-client-go/pulsar.(*producer).SendAsync 0 0% 93.73% 0.97s 1.24% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).SendAsync 0.87s 89.69% | runtime.newobject ----------------------------------------------------------+------------- 0.98s 100% | main.produce.func1 0 0% 93.73% 0.98s 1.25% | github.com/apache/pulsar-client-go/pulsar.(*producer).SendAsync 0.97s 98.98% | github.com/apache/pulsar-client-go/pulsar.(*partitionProducer).SendAsync ----------------------------------------------------------+------------- 9.19s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).start.func1 0 0% 93.73% 9.19s 11.70% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run 8.79s 95.65% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).internalWriteData 0.18s 1.96% | runtime.selectgo ----------------------------------------------------------+------------- 0 0% 93.73% 9.19s 11.70% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).start.func1 9.19s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run ----------------------------------------------------------+------------- 0.91s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readSingleCommand 0 0% 93.73% 0.91s 1.16% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).deserializeCmd 0.82s 90.11% | github.com/golang/protobuf/proto.Unmarshal 0.09s 9.89% | runtime.newobject ----------------------------------------------------------+------------- 3.42s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readSingleCommand 0 0% 93.73% 3.42s 4.36% | github.com/apache/pulsar-client-go/pulsar/internal.(*connectionReader).readAtLeast 3.42s 100% | io.ReadAtLeast ----------------------------------------------------------+------------- 0.62s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*BatchBuilder).Flush 0 0% 93.73% 0.62s 0.79% | github.com/apache/pulsar-client-go/pulsar/internal.serializeBatch 0.41s 66.13% | github.com/golang/protobuf/proto.Marshal ----------------------------------------------------------+------------- 0.97s 100% | main.main 0 0% 93.73% 0.97s 1.24% | github.com/spf13/cobra.(*Command).Execute 0.97s 100% | github.com/spf13/cobra.(*Command).ExecuteC ----------------------------------------------------------+------------- 0.97s 100% | github.com/spf13/cobra.(*Command).Execute 0 0% 93.73% 0.97s 1.24% | github.com/spf13/cobra.(*Command).ExecuteC 0.97s 100% | github.com/spf13/cobra.(*Command).execute ----------------------------------------------------------+------------- 0.97s 100% | github.com/spf13/cobra.(*Command).ExecuteC 0 0% 93.73% 0.97s 1.24% | github.com/spf13/cobra.(*Command).execute 0.97s 100% | main.newProducerCommand.func1 ----------------------------------------------------------+------------- 3.29s 100% | net.(*netFD).Read 0 0% 93.73% 3.29s 4.19% | internal/poll.(*FD).Read 3.25s 98.78% | syscall.syscall ----------------------------------------------------------+------------- 0.97s 100% | runtime.main 0 0% 93.73% 0.97s 1.24% | main.main 0.97s 100% | github.com/spf13/cobra.(*Command).Execute ----------------------------------------------------------+------------- 0.97s 100% | github.com/spf13/cobra.(*Command).execute 0 0% 93.73% 0.97s 1.24% | main.newProducerCommand.func1 0.97s 100% | main.produce ----------------------------------------------------------+------------- 0 0% 93.73% 1.43s 1.82% | main.produce.func1 0.98s 68.53% | github.com/apache/pulsar-client-go/pulsar.(*producer).SendAsync ----------------------------------------------------------+------------- 3.30s 100% | io.ReadAtLeast 0 0% 93.73% 3.30s 4.20% | net.(*conn).Read 3.30s 100% | net.(*netFD).Read ----------------------------------------------------------+------------- 8.74s 100% | github.com/apache/pulsar-client-go/pulsar/internal.(*connection).internalWriteData 0 0% 93.73% 8.74s 11.13% | net.(*conn).Write 8.74s 100% | net.(*netFD).Write ----------------------------------------------------------+------------- 8.74s 100% | net.(*conn).Write 0 0% 93.73% 8.74s 11.13% | net.(*netFD).Write 8.74s 100% | internal/poll.(*FD).Write ----------------------------------------------------------+------------- 0.46s 100% | runtime.mallocgc 0 0% 93.73% 0.46s 0.59% | runtime.(*mcache).nextFree 0.46s 100% | runtime.(*mcache).refill ----------------------------------------------------------+------------- 0.46s 100% | runtime.(*mcache).nextFree 0 0% 93.73% 0.46s 0.59% | runtime.(*mcache).refill 0.46s 100% | runtime.(*mcentral).cacheSpan ----------------------------------------------------------+------------- 6.61s 100% | runtime.systemstack 0 0% 93.73% 6.61s 8.42% | runtime.entersyscallblock_handoff 6.61s 100% | runtime.handoffp ----------------------------------------------------------+------------- 0.57s 100% | runtime.systemstack 0 0% 93.73% 0.57s 0.73% | runtime.exitsyscallfast.func1 0.57s 100% | runtime.exitsyscallfast_pidle ----------------------------------------------------------+------------- 0.57s 100% | runtime.exitsyscallfast.func1 0 0% 93.73% 0.57s 0.73% | runtime.exitsyscallfast_pidle 0.48s 84.21% | runtime.notewakeup ----------------------------------------------------------+------------- 0 0% 93.73% 5.48s 6.98% | runtime.gcBgMarkWorker 5.46s 99.64% | runtime.systemstack ----------------------------------------------------------+------------- 5.61s 100% | runtime.systemstack 0 0% 93.73% 5.61s 7.14% | runtime.gcBgMarkWorker.func2 5.61s 100% | runtime.gcDrain ----------------------------------------------------------+------------- 5.58s 100% | runtime.systemstack 0 0% 93.73% 5.58s 7.11% | runtime.goready.func1 5.57s 99.82% | runtime.notewakeup ----------------------------------------------------------+------------- 0.61s 93.85% | runtime.gosched_m 0 0% 93.73% 0.65s 0.83% | runtime.goschedImpl 0.56s 86.15% | runtime.schedule ----------------------------------------------------------+------------- 6.61s 100% | runtime.entersyscallblock_handoff 0 0% 93.73% 6.61s 8.42% | runtime.handoffp 6.57s 99.39% | runtime.notewakeup ----------------------------------------------------------+------------- 0 0% 93.73% 0.97s 1.24% | runtime.main 0.97s 100% | main.main ----------------------------------------------------------+------------- 0.33s 73.33% | github.com/apache/pulsar-client-go/pulsar/internal.(*BatchBuilder).Flush 0.12s 26.67% | github.com/golang/protobuf/proto.Marshal 0 0% 93.73% 0.45s 0.57% | runtime.makeslice 0.45s 100% | runtime.mallocgc ----------------------------------------------------------+------------- 0 0% 93.73% 15.12s 19.26% | runtime.mstart 12.97s 85.78% | runtime.systemstack 2.15s 14.22% | runtime.mstart1 ----------------------------------------------------------+------------- 2.15s 100% | runtime.mstart 0 0% 93.73% 2.15s 2.74% | runtime.mstart1 0.90s 41.86% | runtime.usleep 0.85s 39.53% | runtime.nanotime 0.39s 18.14% | runtime.notetsleep ----------------------------------------------------------+------------- 0.27s 42.19% | runtime.notetsleep 0 0% 93.73% 0.64s 0.82% | runtime.notetsleep_internal 0.49s 76.56% | runtime.semasleep 0.15s 23.44% | runtime.nanotime ----------------------------------------------------------+------------- 6.57s 43.28% | runtime.handoffp 5.57s 36.69% | runtime.goready.func1 2.48s 16.34% | runtime.schedule 0.48s 3.16% | runtime.exitsyscallfast_pidle 0 0% 93.73% 15.18s 19.33% | runtime.notewakeup 14.72s 96.97% | runtime.pthread_cond_signal ----------------------------------------------------------+------------- 37.43s 100% | runtime.mcall 0 0% 93.73% 37.43s 47.67% | runtime.park_m 37.43s 100% | runtime.schedule ----------------------------------------------------------+------------- ```
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
