反链面板计算逻辑与性能问题

打开软件,不开反链面板,打开一个有上百个反链的文档后,使用正常,此时后台没有在计算反链。

然后打开一下反链面板,之后马上关上,过一会儿再打开一个有上百个反链的文档,理论上来说,这时候我没有打开反链面板,后台应该不会计算这个文档的反链,然而事实上,此时后台确实在计算反链,CPU 占用一直在 20% 以上,所有和引用块相关的功能都不能用,等到 CPU 占用降低到 5% 以下时,我打开反链面板,发现 200 个反链秒出现,说明当时后台确实在计算反链,这是不符合预期的。

此外另一个问题(与上面的问题无关),我开着反链面板,然后我依次点开 10 个文档,后台会依次计算这 10 个文档的反链,好像有 10 个计算任务的队列,得等这 10 个任务全部出队之后才会释放资源,那么,如果我在两个有几百个反链的文档之间反复点击,一下打开这个文档,一下打开另一个文档,那么这个队列将会入队一堆计算任务,假设我在两个文档之间反复点击 10 次,将会入队 20 个计算任务,假设计算两个文档的反链分别都需要 10 秒钟,那么将有 200 秒钟的时间资源被占用,这 200 秒钟 CPU 占用很高,且所有的引用块功能都用不了,处于“假死”状态,这是灾难级的性能问题,而且事实上,这 20 个任务的队列里面,只有最后 1 个任务是有用的,前 19 个任务都是没有意义的,在我打开另一个文档后,当前文档的反链计算任务完全可以直接终止。

1 操作
fangly 在 2021-11-23 11:04:23 更新了该帖

欢迎来到这里!

我们正在构建一个小众社区,大家在这里相互信任,以平等 • 自由 • 奔放的价值观进行分享交流。最终,希望大家能够找到与自己志同道合的伙伴,共同成长。

注册 关于
请输入回帖内容 ...
  • 88250
    订阅者

    面板一旦打开,就会触发请求,请求在内核处理时没法中断。这个估计得再继续考虑一下改进方案。

    1 回复
  • fangly
    订阅者 作者

    帖子中的第一个问题应该是比较好优化的吧,在我关掉反链面板后,之后打开文档就不要触发反链计算请求,现在应该还是会请求的

    1 回复
  • 88250
    订阅者

    可能要记录一下数据是否变动,没有变动的话就不请求了。我们后面优化了看 Issue #3473 · siyuan-note/siyuan

    1 回复
  • fangly
    订阅者 作者

    我没太理解,好像说的不是一个问题 😂

    帖子中的第二个问题可能和“数据是否变动”有关

    但第一个问题和这个没关系吧,无论“数据是否变动”,都没有请求的意义吧,可以看下面这个录屏,我反链面板都关了,打开一个有 199 个反链的文档后,CPU 开始高占用,开始计算反链,这里的计算请求没有必要吧:

    现在时不时地因为后台计算导致引用块悬浮窗没反应,引用块搜索没反应,要等老半天,而且出现频率很高,有点严重影响使用了,相比 1.4.6 以前,体验流畅度差了不少 😭

    1 回复
    3 操作
    fangly 在 2021-11-23 14:39:26 更新了该回帖
    fangly 在 2021-11-23 14:36:43 更新了该回帖
    fangly 在 2021-11-23 14:35:00 更新了该回帖
  • 88250
    订阅者

    这两天我们在内测版上改了再测测看,改成类似 v1.4.6 的事务实现。

    1 回复
  • fangly
    订阅者 作者

    alpha2 事务实现改了之后我觉得舒服了很多,但反链面板的性能上我体验下来感觉还是有提升空间

    200 个反链的文档第一次加载的时候比 alpha1 快一些,但还是要差不多 8 秒钟才能加载出来,第一次加载时候的时间不知道能否再压榨得短一些 😂

    第一次 8 秒钟加载出来后,打开别的文档,再返回来,反链面板能秒出现,这部分应该是 alpha2 新优化的,这个非常舒服,我猜是检查了“数据是否变动”,没变动就不请求了?

    但是过几分钟后再打开这个有 200 个反链的文档又要 8 秒钟加载,这个几分钟我也不清楚是多久,有时候有的文档上百个反链几分钟后仍然秒加载,但有时候有的文档几分钟后又要好久才能加载(都没有修改过,没有数据变动),不知道这里是不是有 bug?

    1 回复
  • 88250
    订阅者

    做了缓存,10 分钟过期。没有缓存的情况下加载就比较慢,a2 已经做了一些优化,现在先暂时这样,有空我们会继续看下能不能再压榨一些性能空间出来。

    1 回复
  • fangly 1
    订阅者 作者

    偶尔假死的时间比较长,看了一下日志,有下面这个信息,是正常的吗?

    E 2021/11/24 16:36:59 block_query.go:111: sql query failed: SELECT id FROM blocks WHERE parent_id = ?%!(EXTRA *errors.errorString=sql: transaction has already been committed or rolled back)
    E 2021/11/24 16:38:02 block_ref_query.go:432: query scan field failed: sql: Rows are closed
    

    尤其是 query scan field failed: sql: Rows are closed 这一条,我发现自从更新 alpha2 之后,日志里面有不少。

    完整 log:

    log.zip

    顺带提一下,a2 经常出现反链面板第一条内容为空的情况(除了第一条,后面的内容都正常),“传递型”和“关联型”都出现过这种情况,刷新反链面板之后恢复正常,而且有点难复现 😂 :

    image.png

    1 回复
    2 操作
    fangly 在 2021-11-24 16:54:03 更新了该回帖
    fangly 在 2021-11-24 16:53:13 更新了该回帖
  • 88250
    订阅者

    不正常,得留意帮忙观察一下什么情况下卡住触发的,谢谢。

    1 回复
  • fangly
    订阅者 作者

    日志里又发现了新东西:

    W 2021/11/25 19:20:54 conf.go:371: data is writing: 
    goroutine 20570 [running]:
    runtime/debug.Stack()
    	D:/go1.17/src/runtime/debug/stack.go:24 +0x65
    github.com/siyuan-note/siyuan-src/kernel/model.WaitForDataWriting()
    	D:/88250/siyuan-src/kernel/model/conf.go:371 +0x77
    github.com/siyuan-note/siyuan-src/kernel/model.Outline({0xc00129c030, 0x16})
    	D:/88250/siyuan-src/kernel/model/outline.go:16 +0x3e
    github.com/siyuan-note/siyuan-src/kernel/api.getDocOutline(0xc001028600)
    	D:/88250/siyuan-src/kernel/api/outline.go:28 +0xf8
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/siyuan-note/siyuan-src/kernel/model.CheckAuth(0xc001028600)
    	D:/88250/siyuan-src/kernel/model/session.go:94 +0x467
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/sessions.Sessions.func1(0xc001028600)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/sessions@v0.0.3/sessions.go:52 +0x18d
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/gzip.(*gzipHandler).Handle(0xc0007ac0f0, 0xc001028600)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/gzip@v0.0.3/handler.go:60 +0x2ed
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1(0xc001028600)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/recovery.go:99 +0x82
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc0002d81a0, 0xc001028600)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:489 +0x63e
    github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc0002d81a0, {0x21d4348, 0xc000cb62a0}, 0xc001028200)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:445 +0x1c5
    net/http.serverHandler.ServeHTTP({0x21d0708}, {0x21d4348, 0xc000cb62a0}, 0xc001028200)
    	D:/go1.17/src/net/http/server.go:2878 +0x43b
    net/http.(*conn).serve(0xc00035af00, {0x21df640, 0xc0007ddcb0})
    	D:/go1.17/src/net/http/server.go:1929 +0xb08
    created by net/http.(*Server).Serve
    	D:/go1.17/src/net/http/server.go:3033 +0x4e8
    

    我的复现方式是:复制一个文档块引用,粘贴,这时候 CPU 占用很高,应该是在后台计算,这个时候鼠标马上移动到某个引用块上,这时候后台还在计算,引用块是没有反应的。然后日志中就会有上面的内容。

    类似这样操作:

    temp111.gif

    1 回复
  • 88250
    订阅者

    嗯,这个是故意打的调试信息,看上去是因为大纲加载卡住了。

    大纲需要查询 H 里面的动态锚文本,而且只能阻塞查询(日志里的 WaitForDataWriting),不阻塞的话大纲没法即时渲染可能的改变。这部分我觉得是缺乏一个数据结构和算法来描述全局变动,如果能维护一个 diff 状态就好很多,还在想办法。

    1 回复
  • fangly
    订阅者 作者

    有的貌似和大纲没有关系:

    W 2021/11/25 19:27:22 conf.go:371: data is writing: 
    goroutine 24469 [running]:
    runtime/debug.Stack()
    	D:/go1.17/src/runtime/debug/stack.go:24 +0x65
    github.com/siyuan-note/siyuan-src/kernel/model.WaitForDataWriting()
    	D:/88250/siyuan-src/kernel/model/conf.go:371 +0x77
    github.com/siyuan-note/siyuan-src/kernel/model.GetDoc({0xc0004ca330, 0x16}, 0x0, {0x0, 0x0}, 0x0, 0xc0006ab5d0)
    	D:/88250/siyuan-src/kernel/model/file.go:317 +0x66
    github.com/siyuan-note/siyuan-src/kernel/api.getDoc(0xc000636c00)
    	D:/88250/siyuan-src/kernel/api/filetree.go:525 +0x2d1
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/siyuan-note/siyuan-src/kernel/model.CheckAuth(0xc000636c00)
    	D:/88250/siyuan-src/kernel/model/session.go:94 +0x467
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/sessions.Sessions.func1(0xc000636c00)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/sessions@v0.0.3/sessions.go:52 +0x18d
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/gzip.(*gzipHandler).Handle(0xc0007ac0f0, 0xc000636c00)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/gzip@v0.0.3/handler.go:60 +0x2ed
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1(0xc000636c00)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/recovery.go:99 +0x82
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc0002d81a0, 0xc000636c00)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:489 +0x63e
    github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc0002d81a0, {0x21d4348, 0xc000138540}, 0xc000636b00)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:445 +0x1c5
    net/http.serverHandler.ServeHTTP({0x21d0708}, {0x21d4348, 0xc000138540}, 0xc000636b00)
    	D:/go1.17/src/net/http/server.go:2878 +0x43b
    net/http.(*conn).serve(0xc00071e0a0, {0x21df640, 0xc0007ddcb0})
    	D:/go1.17/src/net/http/server.go:1929 +0xb08
    created by net/http.(*Server).Serve
    	D:/go1.17/src/net/http/server.go:3033 +0x4e8
    
    1 回复
  • 88250
    订阅者

    打开文档(动态加载块)也需要阻塞,不然数据可能不一致。

    2 回复
  • fangly
    订阅者 作者

    上次提到的这个 bug 有定位到问题吗:

    image.png

    反链面板中某个文档(大概率是最新更新的文档)中的反链项都不显示,刷新之后才会显示

    1 回复
  • 88250
    订阅者

    暂时还没有,今晚继续看。

  • fangly 1
    订阅者 作者

    我把一个文档 A 中某个有很多引用块的列表块 X,剪切到另一个文档 B 中

    然后在文档 B 中对这个列表块 X 中的某个列表项进行了一下折叠操作

    在文档 A 中其他地方复制了一个块引用

    在文档 B 中,在刚才剪切过来的列表块 X 中的某个位置回车新建一个列表项,准备粘贴块引用

    然后出现了内核连接中断

    重新打开之后,发现文档 A 中那个被剪切的列表块 X 没了,但是文档 B 中也没有这个被剪切的列表块 X,也就是文档 A 写入成功,文档 B 写入不成功,这个列表块 X 就彻底消失了,我只能通过历史功能找回这个列表块 X

    这个问题其实最近经常遇到,我每天打开思源的第一件事就会做类似上面的操作

    相关日志:

    I 2021/11/28 12:39:22 transaction.go:110: tx [12012ms]
    W 2021/11/28 12:39:26 conf.go:371: data is writing: 
    goroutine 552 [running]:
    runtime/debug.Stack()
    	D:/go1.17/src/runtime/debug/stack.go:24 +0x65
    github.com/siyuan-note/siyuan-src/kernel/model.WaitForDataWriting()
    	D:/88250/siyuan-src/kernel/model/conf.go:371 +0x77
    github.com/siyuan-note/siyuan-src/kernel/model.GetDoc({0xc0006389a8, 0x16}, 0x0, {0x0, 0x0}, 0x1, 0xc000c455d0)
    	D:/88250/siyuan-src/kernel/model/file.go:317 +0x66
    github.com/siyuan-note/siyuan-src/kernel/api.getDoc(0xc000b00900)
    	D:/88250/siyuan-src/kernel/api/filetree.go:525 +0x2d1
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/siyuan-note/siyuan-src/kernel/model.CheckAuth(0xc000b00900)
    	D:/88250/siyuan-src/kernel/model/session.go:94 +0x467
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/sessions.Sessions.func1(0xc000b00900)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/sessions@v0.0.3/sessions.go:52 +0x18d
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-contrib/gzip.(*gzipHandler).Handle(0xc000822ba0, 0xc000b00900)
    	D:/gogogo/pkg/mod/github.com/gin-contrib/gzip@v0.0.3/handler.go:60 +0x2ed
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.CustomRecoveryWithWriter.func1(0xc000b00900)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/recovery.go:99 +0x82
    github.com/gin-gonic/gin.(*Context).Next(...)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/context.go:165
    github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc0006051e0, 0xc000b00900)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:489 +0x63e
    github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc0006051e0, {0x1c04368, 0xc0012c61c0}, 0xc000a88d00)
    	D:/gogogo/pkg/mod/github.com/gin-gonic/gin@v1.7.4/gin.go:445 +0x1c5
    net/http.serverHandler.ServeHTTP({0x1c00728}, {0x1c04368, 0xc0012c61c0}, 0xc000a88d00)
    	D:/go1.17/src/net/http/server.go:2878 +0x43b
    net/http.(*conn).serve(0xc0007341e0, {0x1c0f660, 0xc000136780})
    	D:/go1.17/src/net/http/server.go:1929 +0xb08
    created by net/http.(*Server).Serve
    	D:/go1.17/src/net/http/server.go:3033 +0x4e8
    F 2021/11/28 12:39:26 transaction.go:76: transaction failed: %!s(<nil>)
    ```
    
    1 回复
  • 88250
    订阅者

    收到,这个需要时间考虑改进方案,先记录 Issue #3508 · siyuan-note/siyuan

    1 回复
  • fangly
    订阅者 作者

    出问题的在哪一步呀,在还没改进之前我要怎么防止这种情况出现呢?

    因为最近我每天一打开思源都会做类似的操作,然后几乎都会崩掉,还是有点难受的,我想先知道下怎么防止这种情况出现,比如在什么操作后多等一下之类的?

    1 回复
  • 88250
    订阅者
    • 剪切
    • 折叠
    • 新建

    这几步都需要数据写入,大概就是等 CPU 降下去以后再做下一步。

    1 回复
  • fangly 1
    订阅者 作者

    又出现内核连接中断,这一次和上面的不太一样,没有剪切和新建操作

    我是先从一个文档的反链面板点击跳转到另一个文档,然后有做折叠展开操作,之后就内核连接中断了

    I 2021/11/29 01:29:34 transaction.go:110: tx [2553ms]
    E 2021/11/29 01:29:39 block_query.go:491: query scan field failed: sql: transaction has already been committed or rolled back
    E 2021/11/29 01:29:39 block_query.go:491: query scan field failed: sql: Rows are closed
    F 2021/11/29 01:30:25 transaction.go:76: transaction failed: %!s(<nil>)
    
    1 回复
  • 88250
    订阅者
请输入回帖内容 ...