运行时间统计

有时候，我们希望能够对调用执行时间做一个统计，对于客户端来说，也就是客户端调用发出前，到客户端收到调用结果的时间统计。对于服务器来说，就是收到客户端调用请求到要发出调用结果的这一段时间的统计。这个功能，通过过滤器也可以实现。

stat_filter.go

package main
 
import (
    "fmt"
    "time"
 
    "github.com/hprose/hprose-golang/rpc"
)
 
type StatFilter struct {
    Prompt string
}
 
func (sf StatFilter) stat(context rpc.Context) {
    startTime := context.GetInt64("startTime")
    if startTime > 0 {
        fmt.Printf("%v takes %d ns.\r\n", sf.Prompt, time.Now().UnixNano()-startTime)
    } else {
        context.SetInt64("startTime", time.Now().UnixNano())
    }
}
 
func (sf StatFilter) InputFilter(data []byte, context rpc.Context) []byte {
    sf.stat(context)
    return data
}
 
func (sf StatFilter) OutputFilter(data []byte, context rpc.Context) []byte {
    sf.stat(context)
    return data
}

main.go

package main
 
import "github.com/hprose/hprose-golang/rpc"
 
func hello(name string) string {
    return "Hello " + name + "!"
}
 
// HelloService is ...
type HelloService struct {
    Hello func(string) (string, error)
}
 
func main() {
    server := rpc.NewTCPServer("")
    server.AddFunction("hello", hello).AddFilter(StatFilter{"Server"})
    server.Handle()
    client := rpc.NewClient(server.URI())
    client.AddFilter(StatFilter{"Client"})
    var helloService *HelloService
    client.UseService(&helloService)
    for i := 0; i < 3; i++ {
        helloService.Hello("World")
    }
    client.Close()
    server.Close()
}

运行该程序，你会看到运行结果：

Server takes 47303 ns.
Client takes 315459 ns.
Server takes 6846 ns.
Client takes 68138 ns.
Server takes 5601 ns.
Client takes 64499 ns.

我们看到后面的调用明显要比第一次调用快的多，这是因为第一次调用涉及到 TCP 连接的建立，以及缓存初始化等操作，一旦这些操作完成了，接下来就会很快了。

在这个程序中，我们还看到了 Context 的应用方式，当然 Context 能做的事情不止于此，后面我们还会看到它的更多功能。