When developing pgrwl - a PostgreSQL WAL receiver - performance is a critical concern.
Every part of the program must be predictable. There should be no hidden bottlenecks.
But what about:
- typos that silently degrade performance?
- missing tests that fail to catch inefficiencies?
- slow logic introduced "just for now"?
- accidental O(n^2) behavior?
These issues are often hard to detect.
The Problem
For instance, you may concatenate a huge template in a loop, but that may be done once outside of the loop. And this will work fine, until the heavy load is reveal that.
Of course you should profile CPU/RAM, and there are a lot of great tools, but sometimes it's not enough.
The Bruteforce Idea
A lazy decision for measuring the whole picture is to to trace each function execution time, and the total number that function being called.
Yeah, that cannot help you to inspect all the loops, nasty conditions, memory leaks, etc... But may help a LOT to find as fast as possible really heavily loaded functions, and start profiling them deeply with more advanced profiling tools.
The Solution
I wrote a KISS library called gotrackfunc that injects timing into each single function in the whole project at one CLI command.
How it works
-
gotrackfuncinjects timing code into all functions - Run your program
- Apply load
- Stop execution
- Analyze the report
It's rough and primitive, but it works!!!
You MUST have a version control system of course, so you can drop
all these changes.
Usage And Example Output
# execute in directory of your project
gotrackfunc ./...
# run your app (a gotrackfunc.log will produced)
go run main.go
# make a report (turn gotrackfunc.log into readable form)
gotrackfunc summarize
In this example I've found that my Put() function is the slowest
part of the whole things. So I can inspect it, refactor, optimize,
write more unit-tests, write integration-tests and measure again.
FUNCTION CALLS TOTAL_NS TOTAL_SEC
-------- ----- -------- ---------
storecrypt.Put 70 23061361400 23.06
receivesuperv.uploadOneFile 35 11606918000 11.61
fsync.Fsync 106 8813968000 8.81
xlog.processOneMsg 4481 6818721600 6.82
xlog.processXLogDataMsg 4481 6814495400 6.81
xlog.CloseWalFile 35 6561511500 6.56
xlog.closeAndRename 35 6559979000 6.56
fsync.FsyncFname 70 6525596900 6.53
receivesuperv.performUploads 2 3036884600 3.04
receivesuperv.uploadFiles 1 3034237400 3.03
fsync.FsyncFnameAndDir 35 435023800 0.44
xlog.WriteAtWalFile 4481 208340500 0.21
cmd.mustInitPgrw 1 201671300 0.20
xlog.NewPgReceiver 1 201671300 0.20
xlog.SyncWalFile 1 48771200 0.05
codec.Flush 35 42261100 0.04
xlog.OpenWalFile 36 16938600 0.02
xlog.createFileAndTruncate 36 11396900 0.01
storecrypt.ListInfo 4 9813800 0.01
receivesuperv.performRetention 2 4906900 0.00
conv.ToUint64 4482 2664000 0.00
receivesuperv.filterFilesToUpload 2 2647200 0.00
fsx.FileExists 35 2628000 0.00
xlog.XLogSegmentOffset 8963 2083300 0.00
conv.Uint64ToInt64 4517 1656300 0.00
cmd.loadConfig 1 1563600 0.00
config.MustLoad 1 1563600 0.00
config.mustLoadCfg 1 1563600 0.00
pipe.CompressAndEncryptOptional 35 1278200 0.00
receivemetrics.AddWALBytesReceived 4481 1121600 0.00
codec.Close 35 1001200 0.00
xlog.sendFeedback 3 690700 0.00
xlog.findStreamingStart 1 608600 0.00
receivemode.Init 1 608600 0.00
storecrypt.NewLocal 1 522500 0.00
xlog.GetSlotInformation 2 522500 0.00
shared.SetupStorage 1 522500 0.00
xlog.parseReadReplicationSlot 2 522500 0.00
cmd.mustInitStorageIfRequired 1 522500 0.00
codec.NewWriter 35 504900 0.00
storecrypt.fullPath 37 504000 0.00
xlog.XLogFileName 36 42900 0.00
shared.InitOptionalHandlers 1 0 0.00
config.IsLocalStor 3 0 0.00
jobq.Start 1 0 0.00
receivemetrics.IncJobsExecuted 4 0 0.00
receivemetrics.IncWALFilesReceived 35 0 0.00
xlog.IsPartialXLogFileName 2 0 0.00
receivemetrics.ObserveJobDuration 4 0 0.00
xlog.ScanWalSegSize 1 0 0.00
cmd.needSupervisorLoop 1 0 0.00
shared.getWriteExt 1 0 0.00
storecrypt.transformsFromName 35 0 0.00
config.checkBackupConfig 1 0 0.00
receivemode.NewReceiveModeService 1 0 0.00
conv.ParseUint32 2 0 0.00
storecrypt.isSupportedWriteExt 1 0 0.00
receivemode.NewReceiveController 1 0 0.00
receivemetrics.IncJobsSubmitted 4 0 0.00
config.checkMode 1 0 0.00
storecrypt.encodePath 35 0 0.00
config.expandEnvsWithPrefix 1 0 0.00
config.checkLogConfig 1 0 0.00
xlog.IsPowerOf2 1 0 0.00
aesgcm.NewChunkedGCMCrypter 1 0 0.00
shared.NewHTTPSrv 1 0 0.00
xlog.XLogSegmentsPerXLogId 72 0 0.00
xlog.IsValidWalSegSize 1 0 0.00
config.checkMainConfig 1 0 0.00
config.checkStorageConfig 1 0 0.00
logger.Init 1 0 0.00
receivesuperv.NewArchiveSupervisor 1 0 0.00
middleware.Middleware 6 0 0.00
xlog.existsTimeLineHistoryFile 1 0 0.00
xlog.IsXLogFileName 2 0 0.00
config.IsExternalStor 1 0 0.00
receivesuperv.log 83 0 0.00
cmd.App 1 0 0.00
xlog.parseShowParameter 2 0 0.00
config.expand 1 0 0.00
jobq.log 8 0 0.00
xlog.updateLastFlushPosition 37 0 0.00
receivemetrics.IncWALFilesUploaded 35 0 0.00
strx.HeredocTrim 1 0 0.00
cmd.checkPgEnvsAreSet 1 0 0.00
storecrypt.NewVariadicStorage 1 0 0.00
middleware.Chain 1 0 0.00
xlog.SetStream 1 0 0.00
jobq.Submit 4 0 0.00
config.String 1 0 0.00
config.validate 1 0 0.00
jobq.NewJobQueue 1 0 0.00
config.checkReceiverConfig 1 0 0.00
xlog.calculateCopyStreamSleepTime 3 0 0.00
middleware.SafeHandlerMiddleware 3 0 0.00
xlog.NewStream 1 0 0.00
conv.Uint32ToInt32 1 0 0.00
xlog.XLByteToSeg 36 0 0.00
cmd.initMetrics 1 0 0.00
xlog.GetShowParameter 2 0 0.00
shared.log 1 0 0.00
xlog.log 107 0 0.00
config.Cfg 3 0 0.00
receivesuperv.filterOlderThan 2 0 0.00
storecrypt.decodePath 70 0 0.00
storecrypt.supportedExts 70 0 0.00
xlog.CurrentOpenWALFileName 37 0 0.00
config.checkStorageModifiersConfig 1 0 0.00
xlog.GetStartupInfo 1 0 0.00
Conclusion
This approach is rough, primitive - and surprisingly effective.
Sometimes, brute force wins.
Links
- WAL receiver project: https://github.com/pgrwl/pgrwl
- Tracking library: https://github.com/hashmap-kz/gotrackfunc
Top comments (0)