diff --git a/qlog/event.go b/qlog/event.go index 41893c957..3c67a3826 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -1,6 +1,7 @@ package qlog import ( + "sort" "time" "github.com/lucas-clemente/quic-go/internal/protocol" @@ -12,10 +13,26 @@ var eventFields = [4]string{"time", "category", "event", "data"} type events []event +var _ sort.Interface = &events{} var _ gojay.MarshalerJSONArray = events{} func (e events) IsNil() bool { return e == nil } +func (e events) Len() int { return len(e) } +func (e events) Less(i, j int) bool { + // Don't use time.Before() here. + // Before() uses monotonic time. + // We need to make sure that the actual exported timestamp are sorted. + return e[i].Time.UnixNano() < e[j].Time.UnixNano() +} +func (e events) Swap(i, j int) { e[i], e[j] = e[j], e[i] } + func (e events) MarshalJSONArray(enc *gojay.Encoder) { + // Event timestamps are taken from multiple go routines. + // For example, the receiving go routine sets the receive time of the packet. + // Therefore, events can end up being slightly out of order. + // It turns out that Go's stable sort implementation is a lot faster in that case. + // See https://gist.github.com/marten-seemann/30251742b378318097e5400ea170c00f for benchmarking code. + sort.Stable(e) for _, ev := range e { enc.Array(ev) } diff --git a/qlog/event_test.go b/qlog/event_test.go index 5112f2132..4a15f502a 100644 --- a/qlog/event_test.go +++ b/qlog/event_test.go @@ -51,4 +51,23 @@ var _ = Describe("Events", func() { Expect(eventFields[3]).To(Equal("data")) Expect(decoded[3].(map[string]interface{})["event"]).To(Equal("details")) }) + + It("sorts events", func() { + now := time.Now() + ev := events{ + event{Time: now.Add(time.Minute), eventDetails: mevent{}}, + event{Time: now, eventDetails: mevent{}}, + } + + buf := &bytes.Buffer{} + enc := gojay.NewEncoder(buf) + Expect(enc.Encode(ev)).To(Succeed()) + var decoded []interface{} + Expect(json.Unmarshal(buf.Bytes(), &decoded)).To(Succeed()) + Expect(decoded).To(HaveLen(2)) + t1 := time.Unix(0, int64(decoded[0].([]interface{})[0].(float64)*1e6)) + t2 := time.Unix(0, int64(decoded[1].([]interface{})[0].(float64)*1e6)) + Expect(t1).To(BeTemporally("~", now, time.Millisecond)) + Expect(t2).To(BeTemporally("~", now.Add(time.Minute), time.Millisecond)) + }) })