反直觉的 go panic log 行号
曦子线上出现了一个奇怪的问题, panic 日志打印的函数栈信息不太符合直觉. 反复检查了代码和线上 commit 号都没有问题.
先看线上的伪代码:
func foo(arg1, arg2, arg3 string) string {
return arg1 + arg2 + arg3
}
func main() {
var m map[int]*string
_ = foo(
*m[1],
*m[1],
fmt.Sprintf(*m[1]),
)
fmt.Println("done")
}panic 信息在第 11 行, 直觉上应该在第 9 行. 因为函数参数的调用顺序应该跟代码的顺序对应起来.
验证函数的参数执行循序
func foo(arg1 string) string {
fmt.Println(arg1)
return arg1
}
func bar(arg1, arg2, arg3 string) string {
return arg1 + arg2 + arg3
}
func main() {
_ = bar(
foo("1"),
foo("2"),
foo("3"),
)
fmt.Println("done")
}这段代码用来测试函数参数的执行顺序, 输出如下:
1
2
3
done说明函数的参数确实是按照参数顺序执行的, 那为什么 panic 日志不符合预期?
查看Order_of_evaluation, 但没有明确说明函数参数里混合 map 和函数的时候的执行顺序.
反编译, 看看内脏
这里为了方便理解, 提供全部代码.
package main
import "fmt"
func foo(arg1, arg2, arg3 string) string {
return arg1 + arg2 + arg3
}
func main() {
var m map[int]*string
_ = foo(
*m[1],
*m[1],
fmt.Sprintf(*m[1]),
)
fmt.Println("done")
}执行 go tool objdump -s 'main' main > objdump.txt, 得到反编译结果:
main.go:15 0x10009df3c f00001c0 ADRP 241664(PC), R0
main.go:15 0x10009df40 91020000 ADD $128, R0, R0
main.go:15 0x10009df44 aa1f03e1 MOVD ZR, R1
main.go:15 0x10009df48 b24003e2 ORR $1, ZR, R2
main.go:15 0x10009df4c 97fd9f11 CALL runtime.mapaccess1_fast64(SB)
main.go:15 0x10009df50 f9400003 MOVD (R0), R3
main.go:15 0x10009df54 f9400060 MOVD (R3), R0
main.go:15 0x10009df58 f9400461 MOVD 8(R3), R1
main.go:15 0x10009df5c aa1f03e2 MOVD ZR, R2
main.go:15 0x10009df60 aa1f03e3 MOVD ZR, R3
main.go:15 0x10009df64 aa0303e4 MOVD R3, R4
main.go:15 0x10009df68 97ffe6d6 CALL fmt.Sprintf(SB)
main.go:15 0x10009df6c f9003fe0 MOVD R0, 120(RSP)
main.go:15 0x10009df70 f90037e1 MOVD R1, 104(RSP)
main.go:13 0x10009df74 f00001c0 ADRP 241664(PC), R0
main.go:13 0x10009df78 91020000 ADD $128, R0, R0
main.go:13 0x10009df7c aa1f03e1 MOVD ZR, R1
main.go:13 0x10009df80 b24003e2 ORR $1, ZR, R2
main.go:13 0x10009df84 97fd9f03 CALL runtime.mapaccess1_fast64(SB)
main.go:13 0x10009df88 f9400003 MOVD (R0), R3
main.go:13 0x10009df8c f9400064 MOVD (R3), R4
main.go:13 0x10009df90 f90043e4 MOVD R4, 128(RSP)
main.go:13 0x10009df94 f9400463 MOVD 8(R3), R3
main.go:13 0x10009df98 f9003be3 MOVD R3, 112(RSP)
main.go:14 0x10009df9c f00001c0 ADRP 241664(PC), R0
main.go:14 0x10009dfa0 91020000 ADD $128, R0, R0
main.go:14 0x10009dfa4 aa1f03e1 MOVD ZR, R1
main.go:14 0x10009dfa8 b24003e2 ORR $1, ZR, R2
main.go:14 0x10009dfac 97fd9ef9 CALL runtime.mapaccess1_fast64(SB)
main.go:14 0x10009dfb0 f9400003 MOVD (R0), R3
main.go:14 0x10009dfb4 f9400064 MOVD (R3), R4
main.go:14 0x10009dfb8 f9400463 MOVD 8(R3), R3
main.go:12 0x10009dfbc d503201f NOOP
main.go:6 0x10009dfc0 910123e0 ADD $72, RSP, R0
main.go:6 0x10009dfc4 f94043e1 MOVD 128(RSP), R1
main.go:6 0x10009dfc8 f9403be2 MOVD 112(RSP), R2
main.go:6 0x10009dfcc f9403fe5 MOVD 120(RSP), R5
main.go:6 0x10009dfd0 f94037e6 MOVD 104(RSP), R6
main.go:14 0x10009dfd4 aa0303e7 MOVD R3, R7
main.go:6 0x10009dfd8 aa0403e3 MOVD R4, R3
main.go:6 0x10009dfdc aa0703e4 MOVD R7, R4
main.go:6 0x10009dfe0 97fecdb4 CALL runtime.concatstring3(SB) 15 13 14 都进行了 runtime.mapaccess1_fast64(SB), 就是 对 m 的 map 访问, 而 15 行被提前了, 其次是 13 14 行. NOOP 后是 foo 的函数实现, 因为编译优化产生了内敛.
关闭内联优化go build -gcflags="all=-l -N" .:
main.go:15 0x10009c938 90000120 ADRP 147456(PC), R0
main.go:15 0x10009c93c 912f0000 ADD $3008, R0, R0
main.go:15 0x10009c940 aa1f03e1 MOVD ZR, R1
main.go:15 0x10009c944 b24003e2 ORR $1, ZR, R2
main.go:15 0x10009c948 97fdab2a CALL runtime.mapaccess1_fast64(SB)
main.go:15 0x10009c94c f9400003 MOVD (R0), R3
main.go:15 0x10009c950 f9400060 MOVD (R3), R0
main.go:15 0x10009c954 f9400461 MOVD 8(R3), R1
main.go:15 0x10009c958 aa1f03e2 MOVD ZR, R2
main.go:15 0x10009c95c aa1f03e3 MOVD ZR, R3
main.go:15 0x10009c960 aa0303e4 MOVD R3, R4
main.go:15 0x10009c964 97fff15b CALL fmt.Sprintf(SB)
main.go:15 0x10009c968 f90027e0 MOVD R0, 72(RSP)
main.go:15 0x10009c96c f9001fe1 MOVD R1, 56(RSP)
main.go:13 0x10009c970 90000120 ADRP 147456(PC), R0
main.go:13 0x10009c974 912f0000 ADD $3008, R0, R0
main.go:13 0x10009c978 aa1f03e1 MOVD ZR, R1
main.go:13 0x10009c97c b24003e2 ORR $1, ZR, R2
main.go:13 0x10009c980 97fdab1c CALL runtime.mapaccess1_fast64(SB)
main.go:13 0x10009c984 f9400003 MOVD (R0), R3
main.go:13 0x10009c988 f9400064 MOVD (R3), R4
main.go:13 0x10009c98c f90033e4 MOVD R4, 96(RSP)
main.go:13 0x10009c990 f9400463 MOVD 8(R3), R3
main.go:13 0x10009c994 f90023e3 MOVD R3, 64(RSP)
main.go:14 0x10009c998 90000120 ADRP 147456(PC), R0
main.go:14 0x10009c99c 912f0000 ADD $3008, R0, R0
main.go:14 0x10009c9a0 aa1f03e1 MOVD ZR, R1
main.go:14 0x10009c9a4 b24003e2 ORR $1, ZR, R2
main.go:14 0x10009c9a8 97fdab12 CALL runtime.mapaccess1_fast64(SB)
main.go:14 0x10009c9ac f9400003 MOVD (R0), R3
main.go:14 0x10009c9b0 f9400062 MOVD (R3), R2
main.go:14 0x10009c9b4 f9400463 MOVD 8(R3), R3
main.go:12 0x10009c9b8 f94033e0 MOVD 96(RSP), R0
main.go:12 0x10009c9bc f94023e1 MOVD 64(RSP), R1
main.go:12 0x10009c9c0 f94027e4 MOVD 72(RSP), R4
main.go:12 0x10009c9c4 f9401fe5 MOVD 56(RSP), R5
main.go:12 0x10009c9c8 97ffffb6 CALL main.foo(SB)
main.go:18 0x10009c9cc d00000e3 ADRP 122880(PC), R3
main.go:18 0x10009c9d0 91158063 ADD $1376, R3, R3 我们可以看到了对 foo 函数的调用, 但是调用顺序依然没有变化.
这就很显然了, 当函数里的参数是函数时, 关闭优化和开启优化都会先执行参数是函数的参数.
结论
一般情况下, 函数会按照从左到右的顺序执行, 如果有函数那么会优先函数, 如果是 map/slice 那里面的顺序并没有明确说明, 切不受编译优化开关影响, 至少现在没有明确的开关可以控制这个顺序.
下面这些 case 都是未定义行为:
a := 1
f := func() int { a++; return a }
x := []int{a, f()} // x may be [1, 2] or [2, 2]: evaluation order between a and f() is not specified
m := map[int]int{a: 1, a: 2} // m may be {2: 1} or {2: 2}: evaluation order between the two map assignments is not specified
n := map[int]int{a: f()} // n may be {2: 3} or {3: 3}: evaluation order between the key and the value is not specified也就是没有明确的执行循序.