您好,登錄后才能下訂單哦!
作者 |?楊成立(忘籬) 阿里巴巴高級技術專家
關注“阿里巴巴云原生”公眾號,回復 Go 即可查看清晰知識大圖!
導讀:從問題本身出發,不局限于 Go 語言,探討服務器中常常遇到的問題,最后回到 Go 如何解決這些問題,為大家提供 Go 開發的關鍵技術指南。我們將以系列文章的形式推出《Go 開發的關鍵技術指南》,共有 4 篇文章,本文為第 2 篇。
在 C/C++ 中,
如果能有一種方案,將指針和內存都管理起來,避免用戶錯誤訪問和釋放,這樣雖然浪費了一部分的 CPU,但是可以在快速變化的業務中避免這些頭疼的問題。在現代的高級語言中,比如 Java、Python 和 JS 的異常,以及 Go 的 panic-recover 都是這種機制。
畢竟,用一些 CPU 換得快速迭代中的不 Crash,怎么算都是劃得來的。
Go 有?Defer, Panic, and Recover。其中 defer 一般用在資源釋放或者捕獲 panic。而 panic 是中止正常的執行流程,執行所有的 defer,返回調用函數繼續 panic;主動調用 panic 函數,還有些運行時錯誤都會進入 panic 過程。最后 recover 是在 panic 時獲取控制權,進入正常的執行邏輯。
注意 recover 只有在 defer 函數中才有用,在 defer 的函數調用的函數中 recover 不起作用,如下實例代碼不會 recover:
go
package main
import "fmt"
func main() {
f := func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}
defer func() {
f()
} ()
panic("ok")
}
執行時依舊會 panic,結果如下:
$ go run t.go
panic: ok
goroutine 1 [running]:
main.main()
/Users/winlin/temp/t.go:16 +0x6b
exit status 2
有些情況是不可以被捕獲,程序會自動退出,這種都是無法正常 recover。當然,一般的 panic 都是能捕獲的,比如 Slice 越界、nil 指針、除零、寫關閉的 chan。
下面是 Slice 越界的例子,recover 可以捕獲到:
go
package main
import (
"fmt"
)
func main() {
defer func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}()
b := []int{0, 1}
fmt.Println("Hello, playground", b[2])
}
下面是 nil 指針被引用的例子,recover 可以捕獲到:
go
package main
import (
"bytes"
"fmt"
)
func main() {
defer func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}()
var b *bytes.Buffer
fmt.Println("Hello, playground", b.Bytes())
}
下面是除零的例子,recover 可以捕獲到:
go
package main
import (
"fmt"
)
func main() {
defer func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}()
var v int
fmt.Println("Hello, playground", 1/v)
}
下面是寫關閉的 chan 的例子,recover 可以捕獲到:
go
package main
import (
"fmt"
)
func main() {
defer func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}()
c := make(chan bool)
close(c)
c <- true
}
一般 recover 后會判斷是否 err,有可能需要處理特殊的 error,一般也需要打印日志或者告警,給一個 recover 的例子:
package main
import (
"fmt"
)
type Handler interface {
Filter(err error, r interface{}) error
}
type Logger interface {
Ef(format string, a ...interface{})
}
// Handle panic by hdr, which filter the error.
// Finally log err with logger.
func HandlePanic(hdr Handler, logger Logger) error {
return handlePanic(recover(), hdr, logger)
}
type hdrFunc func(err error, r interface{}) error
func (v hdrFunc) Filter(err error, r interface{}) error {
return v(err, r)
}
type loggerFunc func(format string, a ...interface{})
func (v loggerFunc) Ef(format string, a ...interface{}) {
v(format, a...)
}
// Handle panic by hdr, which filter the error.
// Finally log err with logger.
func HandlePanicFunc(hdr func(err error, r interface{}) error,
logger func(format string, a ...interface{}),
) error {
var f Handler
if hdr != nil {
f = hdrFunc(hdr)
}
var l Logger
if logger != nil {
l = loggerFunc(logger)
}
return handlePanic(recover(), f, l)
}
func handlePanic(r interface{}, hdr Handler, logger Logger) error {
if r != nil {
err, ok := r.(error)
if !ok {
err = fmt.Errorf("r is %v", r)
}
if hdr != nil {
err = hdr.Filter(err, r)
}
if err != nil && logger != nil {
logger.Ef("panic err %+v", err)
}
return err
}
return nil
}
func main() {
func() {
defer HandlePanicFunc(nil, func(format string, a ...interface{}) {
fmt.Println(fmt.Sprintf(format, a...))
})
panic("ok")
}()
logger := func(format string, a ...interface{}) {
fmt.Println(fmt.Sprintf(format, a...))
}
func() {
defer HandlePanicFunc(nil, logger)
panic("ok")
}()
}
對于庫如果需要啟動 goroutine,如何 recover 呢?
errChannel <- conn.Handshake()
?;if err := recover(); err != nil && err != ErrAbortHandler {
?;下面看看一些情況是無法捕獲的,包括(不限于):
sync.Map
?解決這個問題。Map 競爭寫導致 panic 的實例代碼如下:
go
package main
import (
"fmt"
"time"
)
func main() {
m := map[string]int{}
p := func() {
defer func() {
if r := recover(); r != nil {
fmt.Println(r)
}
}()
for {
m["t"] = 0
}
}
go p()
go p()
time.Sleep(1 * time.Second)
}
注意:如果編譯時加了?
-race
,其他競爭條件也會退出,一般用于死鎖檢測,但這會導致嚴重的性能問題,使用需要謹慎。備注:一般標準庫中通過?
throw
?拋出的錯誤都是無法 recover 的,搜索了下 Go1.11 一共有 690 個地方有調用 throw。
Go1.2 引入了能使用的最多線程數限制?ThreadLimit,如果超過了就 panic,這個 panic 是無法 recover 的。
fatal error: thread exhaustion
runtime stack:
runtime.throw(0x10b60fd, 0x11)
/usr/local/Cellar/go/1.8.3/libexec/src/runtime/panic.go:596 +0x95
runtime.mstart()
/usr/local/Cellar/go/1.8.3/libexec/src/runtime/proc.go:1132
默認是 1 萬個物理線程,我們可以調用?runtime
?的?debug.SetMaxThreads
?設置最大線程數。
SetMaxThreads sets the maximum number of operating system threads that the Go program can use. If it attempts to use more than this many, the program crashes. SetMaxThreads returns the previous setting. The initial setting is 10,000 threads.
用這個函數設置程序能使用的最大系統線程數,如果超過了程序就 crash,返回的是之前設置的值,默認是 1 萬個線程。
The limit controls the number of operating system threads, not the number of goroutines. A Go program creates a new thread only when a goroutine is ready to run but all the existing threads are blocked in system calls, cgo calls, or are locked to other goroutines due to use of runtime.LockOSThread.
注意限制的并不是 goroutine 的數目,而是使用的系統線程的限制。goroutine 啟動時,并不總是新開系統線程,只有當目前所有的物理線程都阻塞在系統調用、cgo 調用,或者顯示有調用?runtime.LockOSThread
?時。
SetMaxThreads is useful mainly for limiting the damage done by programs that create an unbounded number of threads. The idea is to take down the program before it takes down the operating system.
這個是最后的防御措施,可以在程序干死系統前把有問題的程序干掉。
舉一個簡單的例子,限制使用 10 個線程,然后用?runtime.LockOSThread
?來綁定 goroutine 到系統線程,可以看到沒有創建 10 個 goroutine 就退出了(runtime 也需要使用線程)。參考下面的例子 Playground: ThreadLimit:
go
package main
import (
"fmt"
"runtime"
"runtime/debug"
"sync"
"time"
)
func main() {
nv := 10
ov := debug.SetMaxThreads(nv)
fmt.Println(fmt.Sprintf("Change max threads %d=>%d", ov, nv))
var wg sync.WaitGroup
c := make(chan bool, 0)
for i := 0; i < 10; i++ {
fmt.Println(fmt.Sprintf("Start goroutine #%v", i))
wg.Add(1)
go func() {
c <- true
defer wg.Done()
runtime.LockOSThread()
time.Sleep(10 * time.Second)
fmt.Println("Goroutine quit")
}()
<- c
fmt.Println(fmt.Sprintf("Start goroutine #%v ok", i))
}
fmt.Println("Wait for all goroutines about 10s...")
wg.Wait()
fmt.Println("All goroutines done")
}
運行結果如下:
bash
Change max threads 10000=>10
Start goroutine #0
Start goroutine #0 ok
......
Start goroutine #6
Start goroutine #6 ok
Start goroutine #7
runtime: program exceeds 10-thread limit
fatal error: thread exhaustion
runtime stack:
runtime.throw(0xffdef, 0x11)
/usr/local/go/src/runtime/panic.go:616 +0x100
runtime.checkmcount()
/usr/local/go/src/runtime/proc.go:542 +0x100
......
/usr/local/go/src/runtime/proc.go:1830 +0x40
runtime.startm(0x1040e000, 0x1040e000)
/usr/local/go/src/runtime/proc.go:2002 +0x180
從這次運行可以看出,限制可用的物理線程為 10 個,其中系統占用了 3 個物理線程,user-level 可運行 7 個線程,開啟第 8 個線程時就崩潰了。
注意這個運行結果在不同的 go 版本是不同的,比如 Go1.8 有時候啟動 4 到 5 個 goroutine 就會崩潰。
而且加 recover 也無法恢復,參考下面的實例代碼。
可見這個機制是最后的防御,不能突破的底線。我們在線上服務時,曾經因為 block 的 goroutine 過多,導致觸發了這個機制。
go
package main
import (
"fmt"
"runtime"
"runtime/debug"
"sync"
"time"
)
func main() {
defer func() {
if r := recover(); r != nil {
fmt.Println("main recover is", r)
}
} ()
nv := 10
ov := debug.SetMaxThreads(nv)
fmt.Println(fmt.Sprintf("Change max threads %d=>%d", ov, nv))
var wg sync.WaitGroup
c := make(chan bool, 0)
for i := 0; i < 10; i++ {
fmt.Println(fmt.Sprintf("Start goroutine #%v", i))
wg.Add(1)
go func() {
c <- true
defer func() {
if r := recover(); r != nil {
fmt.Println("main recover is", r)
}
} ()
defer wg.Done()
runtime.LockOSThread()
time.Sleep(10 * time.Second)
fmt.Println("Goroutine quit")
}()
<- c
fmt.Println(fmt.Sprintf("Start goroutine #%v ok", i))
}
fmt.Println("Wait for all goroutines about 10s...")
wg.Wait()
fmt.Println("All goroutines done")
}
如何避免程序超過線程限制被干掉?一般可能阻塞在 system call,那么什么時候會阻塞?還有,GOMAXPROCS?又有什么作用呢?
The GOMAXPROCS variable limits the number of operating system threads that can execute user-level Go code simultaneously. There is no limit to the number of threads that can be blocked in system calls on behalf of Go code; those do not count against the GOMAXPROCS limit. This package's GOMAXPROCS function queries and changes the limit.
GOMAXPROCS sets the maximum number of CPUs that can be executing simultaneously and returns the previous setting. If n < 1, it does not change the current setting. The number of logical CPUs on the local machine can be queried with NumCPU. This call will go away when the scheduler improves.
可見 GOMAXPROCS 只是設置 user-level 并行執行的線程數,也就是真正執行的線程數 。實際上如果物理線程阻塞在 system calls,會開啟更多的物理線程。關于這個參數的說明,文章《Number of threads used by goroutine》解釋得很清楚:
There is no direct correlation. Threads used by your app may be less than, equal to or more than 10.
So if your application does not start any new goroutines, threads count will be less than 10.
If your app starts many goroutines (>10) where none is blocking (e.g. in system calls), 10 operating system threads will execute your goroutines simultaneously.
If your app starts many goroutines where many (>10) are blocked in system calls, more than 10 OS threads will be spawned (but only at most 10 will be executing user-level Go code).
設置 GOMAXPROCS 為 10:如果開啟的 goroutine 小于 10 個,那么物理線程也小于 10 個。如果有很多 goroutines,但是沒有阻塞在 system calls,那么只有 10 個線程會并行執行。如果有很多 goroutines 同時超過 10 個阻塞在 system calls,那么超過 10 個物理線程會被創建,但是只有 10 個活躍的線程執行 user-level 代碼。
那么什么時候會阻塞在 system blocking 呢?例子《Why does it not create many threads when many goroutines are blocked in writing》解釋很清楚,雖然設置了 GOMAXPROCS 為 1,但實際上還是開啟了 12 個線程,每個 goroutine 一個物理線程,具體執行下面的代碼 Writing Large Block:
go
package main
import (
"io/ioutil"
"os"
"runtime"
"strconv"
"sync"
)
func main() {
runtime.GOMAXPROCS(1)
data := make([]byte, 128*1024*1024)
var wg sync.WaitGroup
for i := 0; i < 10; i++ {
wg.Add(1)
go func(n int) {
defer wg.Done()
for {
ioutil.WriteFile("testxxx"+strconv.Itoa(n), []byte(data), os.ModePerm)
}
}(i)
}
wg.Wait()
}
運行結果如下:
Mac chengli.ycl$ time go run t.go
real 1m44.679s
user 0m0.230s
sys 0m53.474s
雖然 GOMAXPROCS 設置為 1,實際上創建了 12 個物理線程。
有大量的時間是在 sys 上面,也就是 system calls。
So I think the syscalls were exiting too quickly in your original test to show the effect you were expecting.
Effective Go?中的解釋:
Goroutines are multiplexed onto multiple OS threads so if one should block, such as while waiting for I/O, others continue to run. Their design hides many of the complexities of thread creation and management.
由此可見,如果程序出現因為超過線程限制而崩潰,那么可以在出現瓶頸時,用 linux 工具查看系統調用的統計,看哪些系統調用導致創建了過多的線程。
錯誤處理是現實中經常碰到的、難以處理好的問題,下面會從下面幾個方面探討錯誤處理:
我們總會遇到非預期的非正常情況,有一種是符合預期的,比如函數返回 error 并處理,這種叫做可以預見到的錯誤,還有一種是預見不到的比如除零、空指針、數組越界等叫做 panic,panic 的處理主要參考?Defer, Panic, and Recover。
錯誤處理的模型一般有兩種,一般是錯誤碼模型比如 C/C++ 和 Go,還有異常模型比如 Java 和 C#。Go 沒有選擇異常模型,因為錯誤碼比異常更有優勢,參考文章《Cleaner, more elegant, and wrong》以及《Cleaner, more elegant, and harder to recognize》。
看下面的代碼:
try {
AccessDatabase accessDb = new AccessDatabase();
accessDb.GenerateDatabase();
} catch (Exception e) {
// Inspect caught exception
}
public void GenerateDatabase()
{
CreatePhysicalDatabase();
CreateTables();
CreateIndexes();
}
這段代碼的錯誤處理有很多問題,比如如果?CreateIndexes
?拋出異常,會導致數據庫和表不會刪除,造成臟數據。從代碼編寫者和維護者的角度看這兩個模型,會比較清楚:
cdn.com/92bd3a63896ae8648d0368e6847b14cc50ed113e.png">
錯誤處理不容易做好,要說容易那說明做錯了;要把錯誤處理寫對了,基于錯誤碼模型雖然很難,但比異常模型簡單。
如果使用錯誤碼模型,非常容易就能看出錯誤處理沒有寫對,也能很容易知道做得好不好;要知道是否做得非常好,錯誤碼模型也不太容易。
如果使用異常模型,無論做的好不好都很難知道,而且也很難知道怎么做好。
<a name="19daca20"></a>
Go 官方的 error 介紹,簡單一句話就是返回錯誤對象的方式,參考《Error handling and Go》,解釋了 error 是什么?如何判斷具體的錯誤?以及顯式返回錯誤的好處。
文中舉的例子就是打開文件錯誤:
func Open(name string) (file *File, err error)
Go 可以返回多個值,最后一個一般是 error,我們需要檢查和處理這個錯誤,這就是 Go 的錯誤處理的官方介紹:
if err := Open("src.txt"); err != nil {
// Handle err
}
看起來非常簡單的錯誤處理,有什么難的呢?稍等,在 Go2 的草案中,提到的三個點?Error Handling、Error Values和?Generics 泛型,兩個點都是錯誤處理的,這說明了 Go1 中對于錯誤是有改進的地方。
再詳細看下 Go2 的草案,錯誤處理:Error Handling?中,主要描述了發生錯誤時的重復代碼,以及不能便捷處理錯誤的情況。比如草案中舉的這個例子 No Error Handling: CopyFile,沒有做任何錯誤處理:
package main
import (
"fmt"
"io"
"os"
)
func CopyFile(src, dst string) error {
r, _ := os.Open(src)
defer r.Close()
w, _ := os.Create(dst)
io.Copy(w, r)
w.Close()
return nil
}
func main() {
fmt.Println(CopyFile("src.txt", "dst.txt"))
}
還有草案中這個例子 Not Nice and still Wrong: CopyFile,錯誤處理是特別啰嗦,而且比較明顯有問題:
package main
import (
"fmt"
"io"
"os"
)
func CopyFile(src, dst string) error {
r, err := os.Open(src)
if err != nil {
return err
}
defer r.Close()
w, err := os.Create(dst)
if err != nil {
return err
}
defer w.Close()
if _, err := io.Copy(w, r); err != nil {
return err
}
if err := w.Close(); err != nil {
return err
}
return nil
}
func main() {
fmt.Println(CopyFile("src.txt", "dst.txt"))
}
當?io.Copy
?或?w.Close
?出現錯誤時,目標文件實際上是有問題,那應該需要刪除 dst 文件的。而且需要給出錯誤時的信息,比如是哪個文件,不能直接返回 err。所以 Go 中正確的錯誤處理,應該是這個例子 Good: CopyFile,雖然啰嗦繁瑣不簡潔:
package main
import (
"fmt"
"io"
"os"
)
func CopyFile(src, dst string) error {
r, err := os.Open(src)
if err != nil {
return fmt.Errorf("copy %s %s: %v", src, dst, err)
}
defer r.Close()
w, err := os.Create(dst)
if err != nil {
return fmt.Errorf("copy %s %s: %v", src, dst, err)
}
if _, err := io.Copy(w, r); err != nil {
w.Close()
os.Remove(dst)
return fmt.Errorf("copy %s %s: %v", src, dst, err)
}
if err := w.Close(); err != nil {
os.Remove(dst)
return fmt.Errorf("copy %s %s: %v", src, dst, err)
}
return nil
}
func main() {
fmt.Println(CopyFile("src.txt", "dst.txt"))
}
具體應該如何簡潔的處理錯誤,可以讀?Error Handling,大致是引入關鍵字 handle 和 check,由于本文重點側重 Go1 如何錯誤處理,就不展開分享了。
明顯上面每次都返回的?fmt.Errorf
?信息也是不夠的,所以 Go2 還對于錯誤的值有提案,參考?Error Values。大規模程序應該面向錯誤編程和測試,同時錯誤應該包含足夠的信息。
Go1 中判斷 error 具體是什么錯誤,有以下幾種辦法:
io.EOF
?這個全局變量,那么可以直接比較是否是這個錯誤;os.IsNotExist
?判斷是否是指定錯誤;error.Error()
?返回的字符串匹配,看是否是某個錯誤。在復雜程序中,有用的錯誤需要包含調用鏈的信息。例如,考慮一次數據庫寫,可能調用了 RPC,RPC 調用了域名解析,最終是沒有權限讀?/etc/resolve.conf
?文件,那么給出下面的調用鏈會非常有用:
write users database: call myserver.Method: \
dial myserver:3333: open /etc/resolv.conf: permission denied
<a name="43f7325f"></a>
由于 Go1 的錯誤值沒有完整的解決這個問題,才導致出現非常多的錯誤處理的庫,比如:
errors.Is
、errors.As
?和?errors.Match
;%+v
?來格式化錯誤的額外信息比如堆棧;pkg/errors
?的 Cause 返回最底層的錯誤不同,它只反饋錯誤鏈的下一個錯誤;Go1.13 改進了 errors,參考如下實例代碼:
package main
import (
"errors"
"fmt"
"io"
)
func foo() error {
return fmt.Errorf("read err: %w", io.EOF)
}
func bar() error {
if err := foo(); err != nil {
return fmt.Errorf("foo err: %w", err)
}
return nil
}
func main() {
if err := bar(); err != nil {
fmt.Printf("err: %+v\n", err)
fmt.Printf("unwrap: %+v\n", errors.Unwrap(err))
fmt.Printf("unwrap of unwrap: %+v\n", errors.Unwrap(errors.Unwrap(err)))
fmt.Printf("err is io.EOF? %v\n", errors.Is(err, io.EOF))
}
}
運行結果如下:
err: foo err: read err: EOF
unwrap: read err: EOF
unwrap of unwrap: EOF
err is io.EOF? true
從上面的例子可以看出:
errors.Is
?能判斷出是否是最里面的那個 error。另外,錯誤處理往往和 log 是容易混為一談的,因為遇到錯誤一般會打日志,特別是在 C/C 中返回錯誤碼一般都會打日志記錄下,有時候還會記錄一個全局的錯誤碼比如 linux 的 errno,而這種習慣,導致 error 和 log 混淆造成比較大的困擾。考慮以前寫了一個 C 的服務器,出現錯誤時會在每一層打印日志,所以就會形成堆棧式的錯誤日志,便于排查問題,如果只有一個錯誤,不知道調用上下文,排查會很困難:
avc decode avc_packet_type failed. ret=3001
Codec parse video failed, ret=3001
origin hub error, ret=3001
這種比只打印一條日志?origin hub error, ret=3001
?要好,但是還不夠好:
改進后的錯誤日志變成了在底層返回,而不在底層打印在調用層打印,有調用鏈和堆棧,有線程切換的 ID 信息,也有文件的行數:
Error processing video, code=3001 : origin hub : codec parser : avc decoder
[100] video_avc_demux() at [srs_kernel_codec.cpp:676]
[100] on_video() at [srs_app_source.cpp:1076]
[101] on_video_imp() at [srs_app_source:2357]
從 Go2 的描述來說,實際上這個錯誤處理也還沒有考慮完備。從實際開發來說,已經比較實用了。
總結下 Go 的 error,錯誤處理應該注意以下幾點:
推薦用?github.com/pkg/errors?這個錯誤處理的庫,基本上是夠用的,參考 Refine: CopyFile,可以看到 CopyFile 中低級重復的代碼已經比較少了:
package main
import (
"fmt"
"github.com/pkg/errors"
"io"
"os"
)
func CopyFile(src, dst string) error {
r, err := os.Open(src)
if err != nil {
return errors.Wrap(err, "open source")
}
defer r.Close()
w, err := os.Create(dst)
if err != nil {
return errors.Wrap(err, "create dest")
}
nn, err := io.Copy(w, r)
if err != nil {
w.Close()
os.Remove(dst)
return errors.Wrap(err, "copy body")
}
if err := w.Close(); err != nil {
os.Remove(dst)
return errors.Wrapf(err, "close dest, nn=%v", nn)
}
return nil
}
func LoadSystem() error {
src, dst := "src.txt", "dst.txt"
if err := CopyFile(src, dst); err != nil {
return errors.WithMessage(err, fmt.Sprintf("load src=%v, dst=%v", src, dst))
}
// Do other jobs.
return nil
}
func main() {
if err := LoadSystem(); err != nil {
fmt.Printf("err %+v\n", err)
}
}
改寫的函數中,用?
errors.Wrap
?和?errors.Wrapf
?代替了?fmt.Errorf
,我們不記錄 src 和 dst 的值,因為在上層會記錄這個值(參考下面的代碼),而只記錄我們這個函數產生的數據,比如?nn
。
import "github.com/pkg/errors"
func LoadSystem() error {
src, dst := "src.txt", "dst.txt"
if err := CopyFile(src, dst); err != nil {
return errors.WithMessage(err, fmt.Sprintf("load src=%v, dst=%v", src, dst))
}
// Do other jobs.
return nil
}
在這個上層函數中,我們用的是?
errors.WithMessage
?添加了這一層的錯誤信息,包括?src
?和?dst
,所以?CopyFile
?里面就不用重復記錄這兩個數據了。同時我們也沒有打印日志,只是返回了帶完整信息的錯誤。
func main() {
if err := LoadSystem(); err != nil {
fmt.Printf("err %+v\n", err)
}
}
在頂層調用時,我們拿到錯誤,可以決定是打印還是忽略還是送監控系統。
比如我們在調用層打印錯誤,使用?%+v
?打印詳細的錯誤,有完整的信息:
err open src.txt: no such file or directory
open source
main.CopyFile
/Users/winlin/t.go:13
main.LoadSystem
/Users/winlin/t.go:39
main.main
/Users/winlin/t.go:49
runtime.main
/usr/local/Cellar/go/1.8.3/libexec/src/runtime/proc.go:185
runtime.goexit
/usr/local/Cellar/go/1.8.3/libexec/src/runtime/asm_amd64.s:2197
load src=src.txt, dst=dst.txt
但是這個庫也有些小毛病:
CopyFile
?中還是有可能會有重復的信息,還是 Go2 的?handle
?和?check
?方案是最終解決;Wrap
,有時候是調用?WithMessage
(不需要加堆棧時),這個真是非常不好用的地方(這個我們已經修改了庫,可以全部使用 Wrap 不用 WithMessage,會去掉重復的堆棧)。<a name="Logger"></a>
一直在碼代碼,對日志的理解總是不斷在變,大致分為幾個階段:
日志是給人看的,是用來查問題的。出現問題后根據某些條件,去查不同進程或服務的日志。日志的關鍵是不能漏掉信息,漏了關鍵日志,可能就斷了關鍵的線索;
日志必須要被關聯起來,上下文的日志比單個日志更重要。長連接需要根據會話關聯日志;不同業務模型有不同的上下文,比如服務器管理把服務器作為關鍵信息,查詢這個服務器的相關日志;全鏈路跨機器和服務的日志跟蹤,需要定義可追蹤的邏輯 ID;
Note: 推薦閱讀 Kafka 對于 Log 的定義,廣義日志是可以理解的消息,The Log: What every software engineer should know about real-time data's unifying abstraction。
考慮一個服務,處理不同的連接請求:
package main
import (
"context"
"fmt"
"log"
"math/rand"
"os"
"time"
)
type Connection struct {
url string
logger *log.Logger
}
func (v *Connection) Process(ctx context.Context) {
go checkRequest(ctx, v.url)
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
v.logger.Println("Process connection ok")
}
func checkRequest(ctx context.Context, url string) {
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
logger.Println("Check request ok")
}
var logger *log.Logger
func main() {
ctx := context.Background()
rand.Seed(time.Now().UnixNano())
logger = log.New(os.Stdout, "", log.LstdFlags)
for i := 0; i < 5; i++ {
go func(url string) {
connecton := &Connection{}
connecton.url = url
connecton.logger = logger
connecton.Process(ctx)
}(fmt.Sprintf("url #%v", i))
}
time.Sleep(3 * time.Second)
}
這個日志的主要問題,就是有了和沒有差不多,啥也看不出來,常量太多變量太少,缺失了太多的信息。看起來這是個簡單問題,卻經常容易犯這種問題,需要我們在打印每個日志時,需要思考這個日志比較完善的信息是什么。上面程序輸出的日志如下:
2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Process connection ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Check request ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Check request ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Process connection ok
如果完善下上下文信息,代碼可以改成這樣:
type Connection struct {
url string
logger *log.Logger
}
func (v *Connection) Process(ctx context.Context) {
go checkRequest(ctx, v.url)
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
v.logger.Println(fmt.Sprintf("Process connection ok, url=%v, duration=%v", v.url, duration))
}
func checkRequest(ctx context.Context, url string) {
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
logger.Println(fmt.Sprintf("Check request ok, url=%v, duration=%v", url, duration))
}
輸出的日志如下:
2019/11/21 17:11:35 Check request ok, url=url #3, duration=32ms
2019/11/21 17:11:35 Check request ok, url=url #0, duration=226ms
2019/11/21 17:11:35 Process connection ok, url=url #0, duration=255ms
2019/11/21 17:11:35 Check request ok, url=url #4, duration=396ms
2019/11/21 17:11:35 Check request ok, url=url #2, duration=449ms
2019/11/21 17:11:35 Process connection ok, url=url #2, duration=780ms
2019/11/21 17:11:35 Check request ok, url=url #1, duration=1.01s
2019/11/21 17:11:36 Process connection ok, url=url #4, duration=1.099s
2019/11/21 17:11:36 Process connection ok, url=url #3, duration=1.207s
2019/11/21 17:11:36 Process connection ok, url=url #1, duration=1.257s
完善日志信息后,對于服務器特有的一個問題,就是如何關聯上下文,常見的上下文包括:
如果是短連接,一條日志就能描述,那可能要將多個服務的日志關聯起來,將全鏈路的日志作為上下文;
如果是長連接,一般長連接一定會有定時信息,比如每隔 5 秒輸出這個鏈接的碼率和包數,這樣每個鏈接就無法使用一條日志描述了,鏈接本身就是一個上下文;
以上面的代碼為例,可以用請求 URL 來作為上下文。
package main
import (
"context"
"fmt"
"log"
"math/rand"
"os"
"time"
)
type Connection struct {
url string
logger *log.Logger
}
func (v *Connection) Process(ctx context.Context) {
go checkRequest(ctx, v.url)
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
v.logger.Println(fmt.Sprintf("Process connection ok, duration=%v", duration))
}
func checkRequest(ctx context.Context, url string) {
duration := time.Duration(rand.Int()%1500) * time.Millisecond
time.Sleep(duration)
logger.Println(fmt.Sprintf("Check request ok, url=%v, duration=%v", url, duration))
}
var logger *log.Logger
func main() {
ctx := context.Background()
rand.Seed(time.Now().UnixNano())
logger = log.New(os.Stdout, "", log.LstdFlags)
for i := 0; i < 5; i++ {
go func(url string) {
connecton := &Connection{}
connecton.url = url
connecton.logger = log.New(os.Stdout, fmt.Sprintf("[CONN %v] ", url), log.LstdFlags)
connecton.Process(ctx)
}(fmt.Sprintf("url #%v", i))
}
time.Sleep(3 * time.Second)
}
運行結果如下所示:
[CONN url #2] 2019/11/21 17:19:28 Process connection ok, duration=39ms
2019/11/21 17:19:28 Check request ok, url=url #0, duration=149ms
2019/11/21 17:19:28 Check request ok, url=url #1, duration=255ms
[CONN url #3] 2019/11/21 17:19:28 Process connection ok, duration=409ms
2019/11/21 17:19:28 Check request ok, url=url #2, duration=408ms
[CONN url #1] 2019/11/21 17:19:29 Process connection ok, duration=594ms
2019/11/21 17:19:29 Check request ok, url=url #4, duration=615ms
[CONN url #0] 2019/11/21 17:19:29 Process connection ok, duration=727ms
2019/11/21 17:19:29 Check request ok, url=url #3, duration=1.105s
[CONN url #4] 2019/11/21 17:19:29 Process connection ok, duration=1.289s
如果需要查連接 2 的日志,可以 grep 這個?url #2
?關鍵字:
Mac:gogogo chengli.ycl$ grep 'url #2' t.log
[CONN url #2] 2019/11/21 17:21:43 Process connection ok, duration=682ms
2019/11/21 17:21:43 Check request ok, url=url #2, duration=998ms
然鵝,還是發現有不少問題:
解決辦法包括:
SetOutput(io.Writer)
?將日志送給它處理就可以了。當然,這要求函數傳參時需要帶 context.Context,一般在自己的應用程序中可以要求這么做,凡是打日志的地方要帶 context。對于庫,一般可以不打日志,而返回帶堆棧的復雜錯誤的方式,參考?Errors?錯誤處理部分。
點擊下載《不一樣的 雙11 技術:阿里巴巴經濟體云原生實踐》
本書亮點
“阿里巴巴云原生關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦云原生流行技術趨勢、云原生大規模的落地實踐,做最懂云原生開發者的技術圈。”
免責聲明:本站發布的內容(圖片、視頻和文字)以原創、轉載和分享為主,文章觀點不代表本網站立場,如果涉及侵權請聯系站長郵箱:is@yisu.com進行舉報,并提供相關證據,一經查實,將立刻刪除涉嫌侵權內容。