Implement pprof module extension #3773

niklr · 2021-06-14T22:31:58Z

Issue

Test

Unit Test Coverage

go test -cover ./cmd/harmony/

Before:

ok  	github.com/harmony-one/harmony/cmd/harmony	0.266s	coverage: 47.8% of statements

After:

ok  	github.com/harmony-one/harmony/cmd/harmony	0.136s	coverage: 48.5% of statements

Test/Run Logs

When running and stdin is terminal

./harmony -c config_1_0_4.toml 
Old config version detected 1.0.4
Do you want to update config to the latest version: [y/N]
y
Original config backed up to config_1_0_4.toml.backup
Successfully migrated config_1_0_4.toml from 1.0.4 to 2.1.0

When stdin is piped

echo Y | ./harmony -c config_1_0_4.toml 
Old config version detected 1.0.4
Update saved config with `./harmony config update [config_file]`

Operational Checklist

Does this PR introduce backward-incompatible changes to the on-disk data structure and/or the over-the-wire protocol?. (If no, skip to question 8.)
NO
Does this PR introduce backward-incompatible changes NOT related to on-disk data structure and/or over-the-wire protocol? (If no, continue to question 11.)
NO

Manual / cheatsheet

pprof basics

pprof lets you collect CPU profiles, traces, and heap profiles. The normal way to use pprof is:

Run ./harmony --pprof
Run curl localhost:6060/debug/pprof/{profile_name} --output profile.pb.gz to save a profile
Use go tool pprof profile.pb.gz to analyze said profile

pprof profiles

A Profile is a collection of stack traces showing the call sequences that led to instances of a particular event, such as allocation. Packages can create and maintain their own profiles; the most common use is for tracking resources that must be explicitly closed, such as files or network connections.

Each Profile has a unique name. A few profiles are predefined:

goroutine - stack traces of all current goroutines
heap - a sampling of memory allocations of live objects
allocs - a sampling of all past memory allocations
threadcreate - stack traces that led to the creation of new OS threads
block - stack traces that led to blocking on synchronization primitives
mutex - stack traces of holders of contended mutexes

For more information see runtime/pprof docs

A special profile accepted by --pprof.profile.names

cpu - profiles the current process

pprof config

--pprof enable pprof profiling
--pprof.addr string listen address for pprof (default "127.0.0.1:6060")
--pprof.folder string folder to put pprof profiles (default "./profiles")
--pprof.profile.names strings a list of pprof profile names (separated by ,) e.g. cpu,heap,goroutine
--pprof.profile.intervals ints a list of pprof profile interval integer values (separated by ,)
--pprof.profile.debug ints a list of pprof profile debug integer values (separated by ,)

Example 1

./harmony --pprof.profile.names cpu,heap --pprof.profile.intervals 0,10

Saves the cpu and heap profiles in the ./profiles folder. The cpu profile will be saved on shutdown and the heap profile will be saved every 10 seconds.

Example 2

./harmony --pprof.profile.names cpu,heap,goroutine --pprof.profile.intervals 10 --pprof.profile.debug 0,0,2

Saves the cpu, heap and goroutine profiles in the ./profiles folder. All profiles will be saved every 10 seconds.
The goroutine profile will use debug=2 which means to print the goroutine stacks in the same form that a Go program uses when dying due to an unrecovered panic.

niklr · 2021-06-14T22:32:49Z

Test case 1 - Starting harmony without any arguments or config

Running:
./harmony

Result:

Staking mode; node key 02c0db3387d1acba29266e087bb45d29ce71d6f9271f7d3c44c3ad346cb999005f0d268850709c91c4d5620770012f99; -> shard 1
Started RPC server at: 127.0.0.1:9500
Started WS server at: 127.0.0.1:9800

Problems Found: None

Test case 2 - Passing --pprof --pprof.folder ./profiles --pprof.profile.names cpu,heap,goroutine --pprof.profile.intervals 10 --pprof.profile.debug 0,0,2

Running:

./harmony --pprof --pprof.folder ./profiles --pprof.profile.names cpu,heap,goroutine --pprof.profile.intervals 10 --pprof.profile.debug 0,0,2

Result:

Staking mode; node key 02c0db3387d1acba29266e087bb45d29ce71d6f9271f7d3c44c3ad346cb999005f0d268850709c91c4d5620770012f99; -> shard 1
Started RPC server at: 127.0.0.1:9500
Started WS server at: 127.0.0.1:9800

Problems Found: None

Test case 3 Running with config 1.0.2

Running:

./harmony -c config_1_0_2.toml

Result:

Old config version detected 1.0.2
Do you want to update config to the latest version: [y/N]

Staking mode; node key 02c0db3387d1acba29266e087bb45d29ce71d6f9271f7d3c44c3ad346cb999005f0d268850709c91c4d5620770012f99; -> shard 1
Started RPC server at: 127.0.0.1:9500
Started WS server at: 127.0.0.1:9800

Problems Found: None

Test case 4 Running with config 1.0.3

Running:

./harmony -c config_1_0_3.toml

Result:

Old config version detected 1.0.3
Do you want to update config to the latest version: [y/N]

Staking mode; node key 02c0db3387d1acba29266e087bb45d29ce71d6f9271f7d3c44c3ad346cb999005f0d268850709c91c4d5620770012f99; -> shard 1
Started RPC server at: 127.0.0.1:9500
Started WS server at: 127.0.0.1:9800

Problems Found: None

Test case 5 Running with config 1.0.4

Running:

./harmony -c config_1_0_4.toml

Result:

Old config version detected 1.0.4
Do you want to update config to the latest version: [y/N]

Staking mode; node key 02c0db3387d1acba29266e087bb45d29ce71d6f9271f7d3c44c3ad346cb999005f0d268850709c91c4d5620770012f99; -> shard 1
Started RPC server at: 127.0.0.1:9500
Started WS server at: 127.0.0.1:9800

Problems Found: None

JackyWYX

Sorry for the late reply. Some suggestions in the comments. Please fix. Thanks.

api/service/pprof/service.go

cmd/harmony/config.go

cmd/harmony/config_migrations.go

cmd/harmony/flags.go

JackyWYX · 2021-07-07T19:39:01Z

Please rebase and solve the conflict introduced by another config upgrade. Thanks!!

niklr · 2021-07-09T13:01:40Z

Thank your for the review. Really good points indeed! I will try to resolve them asap.

niklr · 2021-07-09T20:10:47Z

Setting the default value in config_migrations.go as follows results in the error Can't convert []([]string) to []string(slice)

migrations["2.1.0"] = func(confTree *toml.Tree) *toml.Tree {
  ...
  if confTree.Get("Pprof.ProfileNames") == nil {
    confTree.Set("Pprof.ProfileNames", []string{})
  }
  ...
  
  confTree.Set("Version", "2.2.0")
  return confTree
}

Changing []string{} to make([]string, 0) has the same result when running config_migrations_test.go

Do you know what I'm missing here @JackyWYX ?

niklr · 2021-07-09T21:31:36Z

Changing []string{} to make([]interface{}, 0) did the trick.

niklr · 2021-07-10T11:38:54Z

All mentioned suggestions and remarks should now be covered. Please review again. @JackyWYX @LeoHChen

Thanks a lot!

api/service/pprof/service.go

JackyWYX

Still some comments out there. Please fix. Thanks!

api/service/pprof/service.go

cmd/harmony/default.go

cmd/harmony/config_migrations.go

go.mod

niklr · 2021-07-15T09:27:59Z

Ready for round 3 @JackyWYX

JackyWYX · 2021-07-19T18:15:07Z

api/service/pprof/service.go

+	}
+	svc.profiles = profiles
+
+	go func() {


Do you mind moving these two lines to service.Start?

JackyWYX · 2021-07-19T18:26:11Z

api/service/pprof/service.go

+// stopCpuProfile stops the current CPU profile, if any
+func stopCpuProfile() {
+	pprof.StopCPUProfile()
+	if cpuFile != nil {


Have you tried testing with go test --race of this line? It seems there is a data race condition of cpuFile.

The race condition can be detected by

implement a unit test with service.Start and last for at least one iteration.

Test with go test --race.

go.mod

JackyWYX · 2021-07-19T18:32:21Z

One last small comments about data racing.

niklr · 2021-07-19T21:47:42Z

Fixed data racing using a mutex and moved the two lines @JackyWYX

JackyWYX

@niklr Thanks for all your work! Impressed :)

@rlan35 @LeoHChen Take a look?

api/service/pprof/service.go

niklr · 2021-07-20T19:30:27Z

Thank you @JackyWYX, that review process was rigorous. :) Makes me appreciate the harmony project even more.

With that, do you consider this bounty as completed? The deadline is approaching quite soon (~4 days).

JackyWYX · 2021-07-21T02:50:29Z

Please resolve the last comment about the variable name lock. Thanks!

rlan35 · 2021-07-21T19:01:28Z

looks good to merge if this is backward-compatible. We should do more testing to make sure no race condition and it won't crash the node.

JackyWYX · 2021-07-21T20:34:55Z

looks good to merge if this is backward-compatible. We should do more testing to make sure no race condition and it won't crash the node.

What kind of testing are you suggesting?

rlan35 · 2021-07-21T20:52:34Z

looks good to merge if this is backward-compatible. We should do more testing to make sure no race condition and it won't crash the node.

What kind of testing are you suggesting?

Like extended period of testing longevity test. Like doing frequent pprof every 1s for 2 hours and see if there is any race condition and other problems.

JackyWYX · 2021-07-21T21:16:43Z

Like extended period of testing longevity test. Like doing frequent pprof every 1s for 2 hours and see if there is any race condition and other problems.

Sound reasonable. @niklr Could you please do this test and give out the machine performance metrics? (Like CPU usage, memory, with / without pprof module)

niklr · 2021-07-21T22:16:42Z

Sure, I will record metrics with the following script tomorrow (getting late here already):

#! /bin/bash
echo "ELAPSED %CPU %MEM" >> output.txt
while :
do
    clear
    ps -p {HARMONY_PID} -o etime,%cpu,%mem | tail -n +2 | tee -a output.txt
    sleep 1s
done

Or do you have any other preferences @JackyWYX ?

JackyWYX · 2021-07-21T22:19:00Z

Or do you have any other preferences @JackyWYX ?

Could you do performance benchmark on this PR and previous code to see the performance difference?

niklr · 2021-07-21T22:24:56Z

10 minutes running the previous code + 2 hours running this PR with pprof enabled (--pprof.profile.names cpu,heap --pprof.profile.intervals 1)

Something like that?

JackyWYX · 2021-07-21T23:09:17Z

10 minutes running the previous code + 2 hours running this PR with pprof enabled (--pprof.profile.names cpu,heap --pprof.profile.intervals 1)

Something like that?

Can you do 2 hours running previous code vs 2 hours running with pprof enabled?

niklr · 2021-07-22T09:21:25Z

Harmony performance profiling over 2 hours

LGTM @JackyWYX @rlan35

JackyWYX requested review from JackyWYX and LeoHChen and removed request for JackyWYX June 29, 2021 22:19

JackyWYX reviewed Jul 7, 2021

View reviewed changes

cmd/harmony/config.go Outdated Show resolved Hide resolved

cmd/harmony/config_migrations.go Show resolved Hide resolved

cmd/harmony/flags.go Outdated Show resolved Hide resolved

cmd/harmony/flags.go Outdated Show resolved Hide resolved

cmd/harmony/flags.go Outdated Show resolved Hide resolved

niklr force-pushed the bounty-46 branch from 5b35c1c to 92568ea Compare July 9, 2021 14:35

niklr added 4 commits July 9, 2021 23:54

Implement pprof module extension

c389986

Fix pprof service tests

88a4617

Set tomlConfigVersion to 2.2.0

ec72821

Fix pprof service related flag and config migration tests

e750a99

niklr force-pushed the bounty-46 branch from b70b47e to e750a99 Compare July 9, 2021 21:55

niklr requested a review from JackyWYX July 10, 2021 13:23

JackyWYX reviewed Jul 14, 2021

View reviewed changes

api/service/pprof/service.go Outdated Show resolved Hide resolved

api/service/pprof/service.go Outdated Show resolved Hide resolved

JackyWYX reviewed Jul 14, 2021

View reviewed changes

Update pprof module extension

e25016d

niklr commented Jul 15, 2021

View reviewed changes

go.mod Show resolved Hide resolved

niklr requested a review from JackyWYX July 15, 2021 09:28

JackyWYX reviewed Jul 19, 2021

View reviewed changes

Fix pprof service race condition

1db0b21

niklr requested a review from JackyWYX July 19, 2021 21:47

JackyWYX approved these changes Jul 20, 2021

View reviewed changes

api/service/pprof/service.go Outdated Show resolved Hide resolved

Rename mutex in pprof service

f2e78f9

rlan35 approved these changes Jul 21, 2021

View reviewed changes

JackyWYX mentioned this pull request Jul 21, 2021

[config] Add p2p.disc.concurrency flag #3829

Merged

LeoHChen merged commit 7cf9c37 into harmony-one:main Jul 23, 2021

MaxMustermann2 mentioned this pull request Dec 3, 2021

Resolve harmony-one/bounties#90: Add revert mechanism for UpdateValidatorWrapper #3939

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement pprof module extension #3773

Implement pprof module extension #3773

niklr commented Jun 14, 2021 •

edited

Loading

niklr commented Jun 14, 2021

JackyWYX left a comment

JackyWYX commented Jul 7, 2021

niklr commented Jul 9, 2021

niklr commented Jul 9, 2021 •

edited

Loading

niklr commented Jul 9, 2021 •

edited

Loading

niklr commented Jul 10, 2021

JackyWYX left a comment

niklr commented Jul 15, 2021

JackyWYX Jul 19, 2021

JackyWYX Jul 19, 2021 •

edited

Loading

JackyWYX commented Jul 19, 2021

niklr commented Jul 19, 2021

JackyWYX left a comment

niklr commented Jul 20, 2021

JackyWYX commented Jul 21, 2021 •

edited

Loading

rlan35 commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

rlan35 commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 22, 2021

Implement pprof module extension #3773

Implement pprof module extension #3773

Conversation

niklr commented Jun 14, 2021 • edited Loading

Issue

Test

Unit Test Coverage

Test/Run Logs

Operational Checklist

Manual / cheatsheet

pprof basics

pprof profiles

pprof config

niklr commented Jun 14, 2021

Test case 1 - Starting harmony without any arguments or config

Test case 2 - Passing --pprof --pprof.folder ./profiles --pprof.profile.names cpu,heap,goroutine --pprof.profile.intervals 10 --pprof.profile.debug 0,0,2

Test case 3 Running with config 1.0.2

Test case 4 Running with config 1.0.3

Test case 5 Running with config 1.0.4

JackyWYX left a comment

Choose a reason for hiding this comment

JackyWYX commented Jul 7, 2021

niklr commented Jul 9, 2021

niklr commented Jul 9, 2021 • edited Loading

niklr commented Jul 9, 2021 • edited Loading

niklr commented Jul 10, 2021

JackyWYX left a comment

Choose a reason for hiding this comment

niklr commented Jul 15, 2021

JackyWYX Jul 19, 2021

Choose a reason for hiding this comment

JackyWYX Jul 19, 2021 • edited Loading

Choose a reason for hiding this comment

JackyWYX commented Jul 19, 2021

niklr commented Jul 19, 2021

JackyWYX left a comment

Choose a reason for hiding this comment

niklr commented Jul 20, 2021

JackyWYX commented Jul 21, 2021 • edited Loading

rlan35 commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

rlan35 commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 21, 2021

JackyWYX commented Jul 21, 2021

niklr commented Jul 22, 2021

niklr commented Jun 14, 2021 •

edited

Loading

niklr commented Jul 9, 2021 •

edited

Loading

niklr commented Jul 9, 2021 •

edited

Loading

JackyWYX Jul 19, 2021 •

edited

Loading

JackyWYX commented Jul 21, 2021 •

edited

Loading