Profile all event handlers

[Stebalien]

We handle events synchronously so event handlers need to be very fast. Currently, they're not 😢.

[Stebalien]

Also, fix them.

[whyrusleeping]

Looks like our changes to the DHT code recently made the DHT's Connected notification block on the secio handshakes finishing:

goroutine 11018914 [semacquire]:
sync.runtime_SemacquireMutex(0xc4454cf89c)
       /home/whyrusleeping/go/src/runtime/sema.go:62 +0x34
sync.(*Mutex).Lock(0xc4454cf898)
       /home/whyrusleeping/go/src/sync/mutex.go:87 +0x9d
gx/ipfs/QmZfwmhbcgSDGqGaoMMYx8jxBGauZw75zPjnZAyfwPso7M/go-libp2p-secio.(*secureSession).Handshake(0xc4454cf680, 0x0, 0x0)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmZfwmhbcgSDGqGaoMMYx8jxBGauZw75zPjnZAyfwPso7M/go-libp2p-secio/protocol.go:93 +0x4f
gx/ipfs/QmZfwmhbcgSDGqGaoMMYx8jxBGauZw75zPjnZAyfwPso7M/go-libp2p-secio.(*secureSession).RemotePeer(0xc4454cf680, 0xc420025600, 0x7f17bd6410b8)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmZfwmhbcgSDGqGaoMMYx8jxBGauZw75zPjnZAyfwPso7M/go-libp2p-secio/interface.go:71 +0x2b
gx/ipfs/QmTi4629yyHJ8qW9sXFjvxJpYcN499tHhERLZYdUqwRU9i/go-libp2p-conn.(*secureConn).RemotePeer(0xc432b32720, 0x7f17bd6410b8, 0xc432b32720)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmTi4629yyHJ8qW9sXFjvxJpYcN499tHhERLZYdUqwRU9i/go-libp2p-conn/secure_conn.go:100 +0x34
gx/ipfs/QmWpJ4y2vxJ6GZpPfQbpVpQxAYS3UeR6AKNbAHxw7wN3qw/go-libp2p-swarm.(*Conn).RemotePeer(0xc449f719d0, 0x1537468, 0xc4200d05e8)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmWpJ4y2vxJ6GZpPfQbpVpQxAYS3UeR6AKNbAHxw7wN3qw/go-libp2p-swarm/swarm_conn.go:64 +0x80
gx/ipfs/QmYi2NvTAiv2xTNJNcnuz3iXDDT1ViBwLFXmDb2g7NogAD/go-libp2p-kad-dht.(*netNotifiee).Connected(0xc4200d0540, 0x1c188a0, 0xc42000b400, 0x1c16280, 0xc449f719d0)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmYi2NvTAiv2xTNJNcnuz3iXDDT1ViBwLFXmDb2g7NogAD/go-libp2p-kad-dht/notif.go:35 +0xd5
gx/ipfs/QmWpJ4y2vxJ6GZpPfQbpVpQxAYS3UeR6AKNbAHxw7wN3qw/go-libp2p-swarm.(*ps2netNotifee).Connected(0xc420b2f000, 0xc449f719d0)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmWpJ4y2vxJ6GZpPfQbpVpQxAYS3UeR6AKNbAHxw7wN3qw/go-libp2p-swarm/swarm.go:387 +0x5e
gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream.(*Swarm).addConn.func2(0x1c11460, 0xc420b2f000)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream/conn.go:225 +0x3a
gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream.(*Swarm).notifyAll.func1(0xc4334eb3f0, 0xc4334eb3e0, 0x1c11460, 0xc420b2f000)
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream/swarm.go:404 +0x60
created by gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream.(*Swarm).notifyAll
       /home/whyrusleeping/gopkg/src/gx/ipfs/QmTMNkpso2WRMevXC8ZxgyBhJvoEHvk24SNeUr9Mf9UM1a/go-peerstream/swarm.go:405 +0x12e

[Stebalien]

The work in libp2p is done here. All that's left is to merge the updated deps into go-ipfs (the updates have also been propagated, I'm just waiting on #4372 before making the PR).

[Stebalien]

Bitswap

It does hold a large lock. I'll have to dig more to see if it's a problem (not looking good but is probably not too hard to fix.

Edit: not an issue (doesn't show up on profiles)

[Stebalien]

At this point, I've gone through quite a few stack traces and used the block and mutex pprof profilers. I'm now reasonably certain that there aren't any more issues with (connection) notifications.

However, we do have two things that show up big time:

1. Dialing. We queue up a bunch of dials. It'd be nice to have dial backpressure in the DHT somehow (Dial backpressure libp2p/go-libp2p-kad-dht#110).
2. DHT. We really need to get DHT pipelining working (DHT Request pipelining libp2p/go-libp2p-kad-dht#92)