internal/profiling/profiling_test.go

/*
 *
 * Copyright 2019 gRPC authors.
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *     http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 *
 */

package profiling

import (
	"fmt"
	"strconv"
	"sync"
	"testing"
	"time"

	"google.golang.org/grpc/internal/grpctest"
	"google.golang.org/grpc/internal/profiling/buffer"
)

type s struct {
	grpctest.Tester
}

func Test(t *testing.T) {
	grpctest.RunSubTests(t, s{})
}

func (s) TestProfiling(t *testing.T) {
	cb, err := buffer.NewCircularBuffer(128)
	if err != nil {
		t.Fatalf("error creating circular buffer: %v", err)
	}

	stat := NewStat("foo")
	cb.Push(stat)
	bar := func(n int) {
		if n%2 == 0 {
			defer stat.NewTimer(strconv.Itoa(n)).Egress()
		} else {
			timer := NewTimer(strconv.Itoa(n))
			stat.AppendTimer(timer)
			defer timer.Egress()
		}
		time.Sleep(1 * time.Microsecond)
	}

	numTimers := int(8 * defaultStatAllocatedTimers)
	for i := 0; i < numTimers; i++ {
		bar(i)
	}

	results := cb.Drain()
	if len(results) != 1 {
		t.Fatalf("len(results) = %d; want 1", len(results))
	}

	statReturned := results[0].(*Stat)
	if stat.Tags != "foo" {
		t.Fatalf("stat.Tags = %s; want foo", stat.Tags)
	}

	if len(stat.Timers) != numTimers {
		t.Fatalf("len(stat.Timers) = %d; want %d", len(stat.Timers), numTimers)
	}

	lastIdx := 0
	for i, timer := range statReturned.Timers {
		// Check that they're in the order of append.
		if n, err := strconv.Atoi(timer.Tags); err != nil && n != lastIdx {
			t.Fatalf("stat.Timers[%d].Tags = %s; wanted %d", i, timer.Tags, lastIdx)
		}

		// Check that the timestamps are consistent.
		if diff := timer.End.Sub(timer.Begin); diff.Nanoseconds() < 1000 {
			t.Fatalf("stat.Timers[%d].End - stat.Timers[%d].Begin = %v; want >= 1000ns", i, i, diff)
		}

		lastIdx++
	}
}

func (s) TestProfilingRace(t *testing.T) {
	stat := NewStat("foo")

	var wg sync.WaitGroup
	numTimers := int(8 * defaultStatAllocatedTimers) // also tests the slice growth code path
	wg.Add(numTimers)
	for i := 0; i < numTimers; i++ {
		go func(n int) {
			defer wg.Done()
			if n%2 == 0 {
				defer stat.NewTimer(strconv.Itoa(n)).Egress()
			} else {
				timer := NewTimer(strconv.Itoa(n))
				stat.AppendTimer(timer)
				defer timer.Egress()
			}
		}(i)
	}
	wg.Wait()

	if len(stat.Timers) != numTimers {
		t.Fatalf("len(stat.Timers) = %d; want %d", len(stat.Timers), numTimers)
	}

	// The timers need not be ordered, so we can't expect them to be consecutive
	// like above.
	seen := make(map[int]bool)
	for i, timer := range stat.Timers {
		n, err := strconv.Atoi(timer.Tags)
		if err != nil {
			t.Fatalf("stat.Timers[%d].Tags = %s; wanted integer", i, timer.Tags)
		}
		seen[n] = true
	}

	for i := 0; i < numTimers; i++ {
		if _, ok := seen[i]; !ok {
			t.Fatalf("seen[%d] = false or does not exist; want it to be true", i)
		}
	}
}

func BenchmarkProfiling(b *testing.B) {
	for routines := 1; routines <= 1<<8; routines <<= 1 {
		b.Run(fmt.Sprintf("goroutines:%d", routines), func(b *testing.B) {
			perRoutine := b.N / routines
			stat := NewStat("foo")
			var wg sync.WaitGroup
			wg.Add(routines)
			for r := 0; r < routines; r++ {
				go func() {
					for i := 0; i < perRoutine; i++ {
						stat.NewTimer("bar").Egress()
					}
					wg.Done()
				}()
			}
			wg.Wait()
		})
	}
}