sort the events before exporting

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)
 	}

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))
+	})
 })