[bug]记一次同步数据问题排查

记一次线上事故排查

具体场景简介：

目前有一个数据同步的场景（Mongodb -> ES）

架构模型如下：

遇到的问题：

任务消费到某一时刻，就会hang住，无法继续消费，channel队列满了以后，导致整个同步任务全面停止

可以很明显的看到已经hang住了，并且最后一条日志明确的显示是阻塞在发送任务上

已经预先开启了pprof，我们看一下当前goroutine阻塞的内容

goroutine profile: total 56
10 @ 0x103d0b2 0x104d4b2 0x1e3ef6c 0x1e443d5 0x1fef5a5 0x1feeaa5 0x106ed81
#    0x1e3ef6b    github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add+0x12b    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229
#    0x1e443d4    aqgs/sync_assistant/internal/toes.ToES+0x394                /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:30
#    0x1fef5a4    aqgs/sync_assistant/internal/task/risk.StorageSoftware+0x604        /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:141
#    0x1feeaa4    aqgs/sync_assistant/internal/task/risk.PoolStorageSoftware+0x1c4    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:106

8 @ 0x103d0b2 0x103d14a 0x106aafe 0x107ac78 0x1c1ada5 0x1c1a7ac 0x106ed81
#    0x106aafd    sync.runtime_notifyListWait+0x13d                                /usr/local/Cellar/go/1.17.5/libexec/src/runtime/sema.go:513
#    0x107ac77    sync.(*Cond).Wait+0x77                                        /usr/local/Cellar/go/1.17.5/libexec/src/sync/cond.go:56
#    0x1c1ada4    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).createConnections.func2+0x1a4    /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/pool.go:616
#    0x1c1a7ab    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).createConnections+0x22b        /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/pool.go:643

4 @ 0x103d0b2 0x104d4b2 0x11a4007 0x106ed81
#    0x11a4006    database/sql.(*DB).connectionOpener+0xc6    /usr/local/Cellar/go/1.17.5/libexec/src/database/sql/sql.go:1196

4 @ 0x103d0b2 0x104d4b2 0x1c1b8eb 0x106ed81
#    0x1c1b8ea    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*pool).maintain+0x54a    /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/pool.go:750

4 @ 0x103d0b2 0x104d4b2 0x1c1e3d5 0x106ed81
#    0x1c1e3d4    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*rttMonitor).start+0x2b4    /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/rtt_monitor.go:95

4 @ 0x103d0b2 0x104d4b2 0x1c22b66 0x1c22a2c 0x106ed81
#    0x1c22b65    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*Server).update.func3+0x105    /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/server.go:493
#    0x1c22a2b    go.mongodb.org/mongo-driver/x/mongo/driver/topology.(*Server).update+0x78b        /Users/songzhibin/go/pkg/mod/go.mongodb.org/mongo-driver@v1.8.3/x/mongo/driver/topology/server.go:556

4 @ 0x103d0b2 0x104d4b2 0x200da5e 0x106ed81
#    0x200da5d    github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1+0xfd    /Users/songzhibin/go/pkg/mod/github.com/go-sql-driver/mysql@v1.6.0/connection.go:614

3 @ 0x103d0b2 0x104d4b2 0x1e3ef6c 0x1e44c7d 0x1e42aba 0x1e4064a 0x106ed81
#    0x1e3ef6b    github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add+0x12b    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229
#    0x1e44c7c    aqgs/sync_assistant/internal/toes.ToES.func1+0x27c            /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:41
#    0x1e42ab9    github.com/elastic/go-elasticsearch/v7/esutil.(*worker).flush+0x1639    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:590
#    0x1e40649    github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run.func1+0x7a9    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:386

2 @ 0x103d0b2 0x103d14a 0x104e185 0x106a805 0x108019c 0x1debab2 0x106ed81
#    0x106a804    sync.runtime_Semacquire+0x24                /usr/local/Cellar/go/1.17.5/libexec/src/runtime/sema.go:56
#    0x108019b    sync.(*WaitGroup).Wait+0xbb                /usr/local/Cellar/go/1.17.5/libexec/src/sync/waitgroup.go:130
#    0x1debab1    github.com/spf13/viper.(*Viper).WatchConfig.func1+0x611    /Users/songzhibin/go/pkg/mod/github.com/spf13/viper@v1.10.1/viper.go:452

2 @ 0x103d0b2 0x104d4b2 0x1454007 0x106ed81
#    0x1454006    github.com/go-redis/redis/v8/internal/pool.(*ConnPool).reaper+0x166    /Users/songzhibin/go/pkg/mod/github.com/go-redis/redis/v8@v8.11.4/internal/pool/pool.go:485

2 @ 0x103d0b2 0x104d4b2 0x1debc4e 0x106ed81
#    0x1debc4d    github.com/spf13/viper.(*Viper).WatchConfig.func1.1+0x14d    /Users/songzhibin/go/pkg/mod/github.com/spf13/viper@v1.10.1/viper.go:413

2 @ 0x106b79b 0x1d2987a 0x1d29405 0x1d2d965 0x1d2bbcd 0x106ed81
#    0x106b79a    syscall.syscall6+0x3a                        /usr/local/Cellar/go/1.17.5/libexec/src/runtime/sys_darwin.go:44
#    0x1d29879    golang.org/x/sys/unix.kevent+0xb9                /Users/songzhibin/go/pkg/mod/golang.org/x/sys@v0.0.0-20211210111614-af8b64212486/unix/zsyscall_darwin_amd64.go:276
#    0x1d29404    golang.org/x/sys/unix.Kevent+0x144                /Users/songzhibin/go/pkg/mod/golang.org/x/sys@v0.0.0-20211210111614-af8b64212486/unix/syscall_bsd.go:417
#    0x1d2d964    github.com/fsnotify/fsnotify.read+0xa4                /Users/songzhibin/go/pkg/mod/github.com/fsnotify/fsnotify@v1.5.1/kqueue.go:512
#    0x1d2bbcc    github.com/fsnotify/fsnotify.(*Watcher).readEvents+0x10c    /Users/songzhibin/go/pkg/mod/github.com/fsnotify/fsnotify@v1.5.1/kqueue.go:275

1 @ 0x1036b3e 0x106af68 0x1e3e75d 0x106ed81
#    0x106af67    os/signal.signal_recv+0x27    /usr/local/Cellar/go/1.17.5/libexec/src/runtime/sigqueue.go:166
#    0x1e3e75c    os/signal.loop+0x1c        /usr/local/Cellar/go/1.17.5/libexec/src/os/signal/signal_unix.go:24

1 @ 0x103d0b2 0x1006e7c 0x1006bfd 0x1fee4b3 0x20adcf8 0x1e54f67 0x1e55d93 0x1e5536f 0x20ad31f 0x20ae037 0x103cc93 0x106ed81
#    0x1fee4b2    aqgs/sync_assistant/internal/task/risk.Software+0xcf2    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:80
#    0x20adcf7    aqgs/sync_assistant/cmd.glob..func4+0x277        /Users/songzhibin/go/src/aqgs/sync_assistant/cmd/risk.go:53
#    0x1e54f66    github.com/spf13/cobra.(*Command).execute+0xb66        /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:860
#    0x1e55d92    github.com/spf13/cobra.(*Command).ExecuteC+0x8b2    /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:974
#    0x1e5536e    github.com/spf13/cobra.(*Command).Execute+0x2e        /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:902
#    0x20ad31e    aqgs/sync_assistant/cmd.Execute+0x3e            /Users/songzhibin/go/src/aqgs/sync_assistant/cmd/root.go:55
#    0x20ae036    main.main+0x16                        /Users/songzhibin/go/src/aqgs/sync_assistant/main.go:21
#    0x103cc92    runtime.main+0x1f2                    /usr/local/Cellar/go/1.17.5/libexec/src/runtime/proc.go:255

1 @ 0x103d0b2 0x100796d 0x10075f8 0x1e3eb56 0x106ed81
#    0x1e3eb55    aqgs/sync_assistant/internal/signal.Register.func1+0x35    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/signal/signal.go:14

1 @ 0x103d0b2 0x1035aae 0x1068fa5 0x1118fa8 0x1119057 0x111db37 0x1374cd2 0x139edf5 0x139d0c7 0x15b6e70 0x15b6825 0x15b8416 0x20ae009 0x106ed81
#    0x1068fa4    internal/poll.runtime_pollWait+0x44        /usr/local/Cellar/go/1.17.5/libexec/src/runtime/netpoll.go:234
#    0x1118fa7    internal/poll.(*pollDesc).wait+0x87        /usr/local/Cellar/go/1.17.5/libexec/src/internal/poll/fd_poll_runtime.go:84
#    0x1119056    internal/poll.(*pollDesc).waitRead+0x36        /usr/local/Cellar/go/1.17.5/libexec/src/internal/poll/fd_poll_runtime.go:89
#    0x111db36    internal/poll.(*FD).Accept+0x4b6        /usr/local/Cellar/go/1.17.5/libexec/src/internal/poll/fd_unix.go:402
#    0x1374cd1    net.(*netFD).accept+0x71            /usr/local/Cellar/go/1.17.5/libexec/src/net/fd_unix.go:173
#    0x139edf4    net.(*TCPListener).accept+0x54            /usr/local/Cellar/go/1.17.5/libexec/src/net/tcpsock_posix.go:140
#    0x139d0c6    net.(*TCPListener).Accept+0x66            /usr/local/Cellar/go/1.17.5/libexec/src/net/tcpsock.go:262
#    0x15b6e6f    net/http.(*Server).Serve+0x52f            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:3002
#    0x15b6824    net/http.(*Server).ListenAndServe+0x164        /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:2931
#    0x15b8415    net/http.ListenAndServe+0xf5            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:3185
#    0x20ae008    aqgs/sync_assistant/cmd.Execute.func1+0x28    /Users/songzhibin/go/src/aqgs/sync_assistant/cmd/root.go:53

1 @ 0x103d0b2 0x103d14a 0x104e185 0x106a925 0x107d691 0x107d3f1 0x1e3fcea 0x106ed81
#    0x106a924    sync.runtime_SemacquireMutex+0x24                        /usr/local/Cellar/go/1.17.5/libexec/src/runtime/sema.go:71
#    0x107d690    sync.(*Mutex).lockSlow+0x270                            /usr/local/Cellar/go/1.17.5/libexec/src/sync/mutex.go:138
#    0x107d3f0    sync.(*Mutex).Lock+0x50                                /usr/local/Cellar/go/1.17.5/libexec/src/sync/mutex.go:81
#    0x1e3fce9    github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).init.func1+0x269    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:319

1 @ 0x1068c05 0x209e6f9 0x209e350 0x20995e7 0x20aa46d 0x20ab2c9 0x15b1783 0x15b4155 0x15b655a 0x15b0618 0x106ed81
#    0x1068c04    runtime/pprof.runtime_goroutineProfileWithLabels+0x24    /usr/local/Cellar/go/1.17.5/libexec/src/runtime/mprof.go:746
#    0x209e6f8    runtime/pprof.writeRuntimeProfile+0x178            /usr/local/Cellar/go/1.17.5/libexec/src/runtime/pprof/pprof.go:724
#    0x209e34f    runtime/pprof.writeGoroutine+0x8f            /usr/local/Cellar/go/1.17.5/libexec/src/runtime/pprof/pprof.go:684
#    0x20995e6    runtime/pprof.(*Profile).WriteTo+0xa6            /usr/local/Cellar/go/1.17.5/libexec/src/runtime/pprof/pprof.go:331
#    0x20aa46c    net/http/pprof.handler.ServeHTTP+0x42c            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/pprof/pprof.go:253
#    0x20ab2c8    net/http/pprof.Index+0xe8                /usr/local/Cellar/go/1.17.5/libexec/src/net/http/pprof/pprof.go:371
#    0x15b1782    net/http.HandlerFunc.ServeHTTP+0x42            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:2047
#    0x15b4154    net/http.(*ServeMux).ServeHTTP+0x134            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:2425
#    0x15b6559    net/http.serverHandler.ServeHTTP+0x479            /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:2879
#    0x15b0617    net/http.(*conn).serve+0x18b7                /usr/local/Cellar/go/1.17.5/libexec/src/net/http/server.go:1930

1 @ 0x106ed81

我这个程序开了10个groutine去同步，我们可以看到10个worker都hang在了这里

goroutine profile: total 56
10 @ 0x103d0b2 0x104d4b2 0x1e3ef6c 0x1e443d5 0x1fef5a5 0x1feeaa5 0x106ed81
#    0x1e3ef6b    github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add+0x12b    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229
#    0x1e443d4    aqgs/sync_assistant/internal/toes.ToES+0x394                /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:30
#    0x1fef5a4    aqgs/sync_assistant/internal/task/risk.StorageSoftware+0x604        /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:141
#    0x1feeaa4    aqgs/sync_assistant/internal/task/risk.PoolStorageSoftware+0x1c4    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:106

主程卡在了发送消息到channel中

1 @ 0x103d0b2 0x1006e7c 0x1006bfd 0x1fee4b3 0x20adcf8 0x1e54f67 0x1e55d93 0x1e5536f 0x20ad31f 0x20ae037 0x103cc93 0x106ed81
#    0x1fee4b2    aqgs/sync_assistant/internal/task/risk.Software+0xcf2    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/task/risk/software.go:80
#    0x20adcf7    aqgs/sync_assistant/cmd.glob..func4+0x277        /Users/songzhibin/go/src/aqgs/sync_assistant/cmd/risk.go:53
#    0x1e54f66    github.com/spf13/cobra.(*Command).execute+0xb66        /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:860
#    0x1e55d92    github.com/spf13/cobra.(*Command).ExecuteC+0x8b2    /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:974
#    0x1e5536e    github.com/spf13/cobra.(*Command).Execute+0x2e        /Users/songzhibin/go/pkg/mod/github.com/spf13/cobra@v1.3.0/command.go:902
#    0x20ad31e    aqgs/sync_assistant/cmd.Execute+0x3e            /Users/songzhibin/go/src/aqgs/sync_assistant/cmd/root.go:55
#    0x20ae036    main.main+0x16                        /Users/songzhibin/go/src/aqgs/sync_assistant/main.go:21
#    0x103cc92    runtime.main+0x1f2                    /usr/local/Cellar/go/1.17.5/libexec/src/runtime/proc.go:255

点进去源码可以看到，阻塞到了select这里

定位到sdk代码

我们切回到 pprof中full groutine stack dump中详细看一下

goroutine 175 [select, 20 minutes]:
github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add(0xc00034a000, {0x2431250, 0xc00003e0d0}, {{0x0, 0x0}, {0x2353093, 0x5}, {0xc002dceea0, 0x2e}, {0x0, ...}, ...})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229 +0x12c
aqgs/sync_assistant/internal/toes.ToES.func1({_, _}, {{0x0, 0x0}, {0x2355caa, 0x6}, {0xc002dceea0, 0x2e}, {0x0, 0x0}, ...}, ...)
    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:41 +0x27d
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).flush(0xc00069e7e0, {0x2431250, 0xc00003e0d0})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:590 +0x163a
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run.func1()
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:386 +0x7aa
created by github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:351 +0x68

goroutine 176 [select, 20 minutes]:
github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add(0xc00034a000, {0x2431250, 0xc00003e0d0}, {{0x0, 0x0}, {0x2353093, 0x5}, {0xc000c1a450, 0x2e}, {0x0, ...}, ...})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229 +0x12c
aqgs/sync_assistant/internal/toes.ToES.func1({_, _}, {{0x0, 0x0}, {0x2355caa, 0x6}, {0xc000c1a450, 0x2e}, {0x0, 0x0}, ...}, ...)
    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:41 +0x27d
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).flush(0xc00069e840, {0x2431250, 0xc00003e0d0})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:590 +0x163a
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run.func1()
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:386 +0x7aa
created by github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:351 +0x68

goroutine 177 [select, 20 minutes]:
github.com/elastic/go-elasticsearch/v7/esutil.(*bulkIndexer).Add(0xc00034a000, {0x2431250, 0xc00003e0d0}, {{0x0, 0x0}, {0x2353093, 0x5}, {0xc0034cc360, 0x2e}, {0x0, ...}, ...})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:229 +0x12c
aqgs/sync_assistant/internal/toes.ToES.func1({_, _}, {{0x0, 0x0}, {0x2355caa, 0x6}, {0xc0034cc360, 0x2e}, {0x0, 0x0}, ...}, ...)
    /Users/songzhibin/go/src/aqgs/sync_assistant/internal/toes/toes.go:41 +0x27d
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).flush(0xc00069e8a0, {0x2431250, 0xc00003e0d0})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:590 +0x163a
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run.func1()
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:386 +0x7aa
created by github.com/elastic/go-elasticsearch/v7/esutil.(*worker).run
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:351 +0x68

我挑出重要的栈信息

goroutine 176 [select, 20 minutes]:
github.com/elastic/go-elasticsearch/v7/esutil.(*worker).flush(0xc00069e840, {0x2431250, 0xc00003e0d0})
    /Users/songzhibin/go/pkg/mod/github.com/elastic/go-elasticsearch/v7@v7.17.0/esutil/bulk_indexer.go:590 +0x163a