Hi everybody
I have a simple program which parses IP addresses and adds them to the
system routing table using the netlink library. The number is routes is
huge (400_000). My parsing part is very simple and fast, and most of the
time is spent in system calls:
File: loadroutes
Type: cpu
Time: Feb 4, 2019 at 12:38am (MSK)
Duration: 4.64s, Total samples = 4.44s (95.74%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3790ms, 85.36% of 4440ms total
Dropped 54 nodes (cum <= 22.20ms)
Showing top 10 nodes out of 80
flat flat% sum% cum cum%
1660ms 37.39% 37.39% 1700ms 38.29% syscall.Syscall6
600ms 13.51% 50.90% 660ms 14.86% syscall.Syscall
590ms 13.29% 64.19% 950ms 21.40%
github.com/vishvananda/netlink/nl.(*NetlinkSocket).Receive
500ms 11.26% 75.45% 500ms 11.26% syscall.RawSyscall
120ms 2.70% 78.15% 120ms 2.70% runtime.futex
100ms 2.25% 80.41% 400ms 9.01% runtime.mallocgc
70ms 1.58% 81.98% 70ms 1.58% runtime.nextFreeFast (inline)
50ms 1.13% 83.11% 3930ms 88.51%
github.com/vishvananda/netlink.(*Handle).routeHandle
50ms 1.13% 84.23% 50ms 1.13%
golang.org/x/text/encoding/charmap.charmapDecoder.Transform
50ms 1.13% 85.36% 60ms 1.35% runtime.heapBitsSetType
graph
https://drive.google.com/file/d/1yENJMWgOH2dmm8XBAq2zDoAah82slzl6/view?usp=sharing
Even though most time is spent in system calls (which seem to be blocking
and can not be speed up at all, but I am not an expert on this), I tried to
add a channel factoring out all the parsing work (a producer channel),
profiling with this channel gives me slightly better times with system
calls, but adds new runtime.futex of roughly 2 seconds:
File: loadroutes
Type: cpu
Time: Feb 4, 2019 at 12:59am (MSK)
Duration: 6.02s, Total samples = 5.34s (88.77%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 4.75s, 88.95% of 5.34s total
Dropped 49 nodes (cum <= 0.03s)
Showing top 10 nodes out of 82
flat flat% sum% cum cum%
2.20s 41.20% 41.20% 2.20s 41.20% runtime.futex
1.11s 20.79% 61.99% 1.18s 22.10% syscall.Syscall6
0.45s 8.43% 70.41% 0.67s 12.55%
github.com/vishvananda/netlink/nl.(*NetlinkSocket).Receive
0.39s 7.30% 77.72% 0.39s 7.30% syscall.RawSyscall
0.35s 6.55% 84.27% 0.38s 7.12% syscall.Syscall
0.06s 1.12% 85.39% 0.11s 2.06% runtime.scang
0.05s 0.94% 86.33% 0.09s 1.69% runtime.exitsyscall
0.05s 0.94% 87.27% 0.05s 0.94% runtime.nextFreeFast (inline)
0.05s 0.94% 88.20% 0.05s 0.94% runtime.procyield
0.04s 0.75% 88.95% 0.04s 0.75% runtime.exitsyscallfast
graph:
https://drive.google.com/file/d/19sHVHKG8a8gwCrYlsTFYh6aOW-kW17gr/view?usp=sharing
I wonder what this new runtime.futex cost (2.20s) is? Is this a constant
cost of sending 400_000 values over a channel? If channel is blocked
waiting (in my case, on a customer) I would expect that this time would not
add to total runtime, but these 2 seconds are seemed to be added to total
runtime (4.64s -> 6.02s), I am not sure, why...
--
You received this message because you are subscribed to the Google Groups
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
For more options, visit https://groups.google.com/d/optout.
