이 주제에서는 Spanner 구성요소를 검사하여 지연 시간의 원인을 찾고 OpenCensus를 사용하여 해당 지연 시간을 시각화하는 방법을 설명합니다.
이 주제의 구성요소에 대한 대략적인 개요는 Spanner 요청의 지연 시간 지점을 참조하세요.
Spanner 클라이언트 라이브러리는 OpenCensus 계측 프레임워크를 사용하여 통계와 trace를 제공합니다. 이 프레임워크는 클라이언트 내부에 대한 유용한 정보를 제공하며 엔드 투 엔드(왕복) 지연 시간 문제를 해결하는 데 도움이 됩니다. 기본적으로 프레임워크는 사용 중지되어 있습니다.
시작하기 전에
지연 시간 지점 식별의 절차에 따라 지연 시간을 표시하는 구성요소를 찾습니다.
클라이언트 왕복 지연 시간 캡처 및 시각화
클라이언트 왕복 지연 시간은 클라이언트가 Google 프런트엔드(GFE) 및 Spanner API 프런트엔드를 통해 데이터베이스로 전송한 Spanner API 요청의 첫 번째 바이트와 클라이언트가 데이터베이스에서 수신한 응답의 마지막 바이트 사이의 시간(밀리초)입니다.
클라이언트 왕복 지연 시간 캡처
클라이언트 왕복 지연 시간을 다음 언어로 캡처할 수 있습니다.
클라이언트 왕복 지연 시간 시각화
측정항목을 검색한 후 Cloud Monitoring에서 클라이언트 왕복 지연 시간을 시각화할 수 있습니다.
다음 예시는 클라이언트 왕복 지연 시간 측정항목의 5번째 백분위수 지연 시간을 보여주는 그래프입니다. 백분위수 지연 시간을 50번째 또는 99번째 백분위수로 변경하려면 애그리게이터 메뉴를 사용합니다.
프로그램에서 roundtrip_latency라는 OpenCensus 뷰를 만듭니다.
이 문자열은 Cloud Monitoring으로 내보낼 때 측정항목 이름의 일부가 됩니다.
GFE 지연 시간 캡처 및 시각화
Google 프런트엔드(GFE) 지연 시간은 Google 네트워크에서 클라이언트의 리모트 프로시져 콜을 수신한 후 GFE가 응답의 첫 번째 바이트를 수신할 때까지의 시간(밀리초)입니다.
GFE 지연 시간 캡처
GFE 지연 시간을 다음 언어로 캡처할 수 있습니다.
Go
// We are in the process of adding support in the Cloud Spanner Go Client Library
// to capture the gfe_latency metric.
import (
"context"
"fmt"
"io"
"strconv"
"strings"
spanner "cloud.google.com/go/spanner/apiv1"
gax "github.com/googleapis/gax-go/v2"
sppb "google.golang.org/genproto/googleapis/spanner/v1"
"google.golang.org/grpc"
"google.golang.org/grpc/metadata"
"contrib.go.opencensus.io/exporter/stackdriver"
"go.opencensus.io/stats"
"go.opencensus.io/stats/view"
"go.opencensus.io/tag"
)
// OpenCensus Tag, Measure and View.
var (
KeyMethod = tag.MustNewKey("grpc_client_method")
GFELatencyMs = stats.Int64("cloud.google.com/go/spanner/gfe_latency",
"Latency between Google's network receives an RPC and reads back the first byte of the response", "ms")
GFELatencyView = view.View{
Name: "cloud.google.com/go/spanner/gfe_latency",
Measure: GFELatencyMs,
Description: "Latency between Google's network receives an RPC and reads back the first byte of the response",
Aggregation: view.Distribution(0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.0, 20.0, 25.0, 30.0, 40.0, 50.0, 65.0, 80.0, 100.0, 130.0, 160.0, 200.0, 250.0,
300.0, 400.0, 500.0, 650.0, 800.0, 1000.0, 2000.0, 5000.0, 10000.0, 20000.0, 50000.0,
100000.0),
TagKeys: []tag.Key{KeyMethod}}
)
func queryWithGFELatency(w io.Writer, db string) error {
projectID, _, _, err := parseDatabaseName(db)
if err != nil {
return err
}
ctx := context.Background()
client, err := spanner.NewClient(ctx)
if err != nil {
return err
}
defer client.Close()
// Register OpenCensus views.
err = view.Register(&GFELatencyView)
if err != nil {
return err
}
// Create OpenCensus Stackdriver exporter.
sd, err := stackdriver.NewExporter(stackdriver.Options{
ProjectID: projectID,
})
if err != nil {
return err
}
// It is imperative to invoke flush before your main function exits
defer sd.Flush()
// Start the metrics exporter
sd.StartMetricsExporter()
defer sd.StopMetricsExporter()
// Create a session.
req := &sppb.CreateSessionRequest{Database: db}
session, err := client.CreateSession(ctx, req)
if err != nil {
return err
}
// Execute a SQL query and retrieve the GFE server-timing header in gRPC metadata.
req2 := &sppb.ExecuteSqlRequest{
Session: session.Name,
Sql: `SELECT SingerId, AlbumId, AlbumTitle FROM Albums`,
}
var md metadata.MD
resultSet, err := client.ExecuteSql(ctx, req2, gax.WithGRPCOptions(grpc.Header(&md)))
if err != nil {
return err
}
for _, row := range resultSet.GetRows() {
for _, value := range row.GetValues() {
fmt.Fprintf(w, "%s ", value.GetStringValue())
}
fmt.Fprintf(w, "\n")
}
// The format is: "server-timing: gfet4t7; dur=[GFE latency in ms]"
srvTiming := md.Get("server-timing")[0]
gfeLtcy, err := strconv.Atoi(strings.TrimPrefix(srvTiming, "gfet4t7; dur="))
if err != nil {
return err
}
// Record GFE t4t7 latency with OpenCensus.
ctx, err = tag.New(ctx, tag.Insert(KeyMethod, "ExecuteSql"))
if err != nil {
return err
}
stats.Record(ctx, GFELatencyMs.M(int64(gfeLtcy)))
return nil
}
GFE 지연 시간 시각화
측정항목을 검색한 후 Cloud Monitoring에서 GFE 지연 시간을 시각화할 수 있습니다.
다음은 GFE 지연 시간 측정항목에 대한 5번째 백분위수 지연 시간을 보여주는 그래프의 예시입니다. 백분위수 지연 시간을 50번째 또는 99번째 백분위수로 변경하려면 애그리게이터 메뉴를 사용합니다.
프로그램에서 gfe_latency라는 OpenCensus 뷰를 만듭니다. 이 문자열은 Cloud Monitoring으로 내보낼 때 측정항목 이름의 일부가 됩니다.
Spanner API 요청 지연 시간 캡처 및 시각화
Spanner API 요청 지연 시간은 Spanner API 프런트엔드에서 수신한 요청의 첫 번째 바이트와 Spanner API 프런트엔드에서 전송한 응답의 마지막 바이트 간의 시간(초)입니다.
Spanner API 요청 지연 시간 캡처
기본적으로 이 지연 시간은 Cloud Monitoring 측정항목의 일부로 제공됩니다.
캡처하고 내보내기 위해 별도의 작업을 수행할 필요가 없습니다.
Spanner API 요청 지연 시간 시각화
측정항목 탐색기 차트 도구를 사용하여 Cloud Monitoring에서 spanner.googleapis.com/api/request_latencies 측정항목에 대한 그래프를 시각화할 수 있습니다.
다음은 Spanner API 요청 지연 시간 측정항목에 대한 5번째 백분위수 지연 시간을 보여주는 그래프의 예시입니다. 백분위수 지연 시간을 50번째 또는 99번째 백분위수로 변경하려면 애그리게이터 메뉴를 사용합니다.
쿼리 지연 시간 캡처 및 시각화
쿼리 지연 시간은 Spanner 데이터베이스에서 SQL 쿼리를 실행하는 데 걸리는 시간(밀리초)입니다.
쿼리 지연 시간 캡처
다음 언어의 쿼리 지연 시간을 캡처할 수 있습니다.
Java
private static final String MILLISECOND = "ms";
static final List<Double> RPC_MILLIS_BUCKET_BOUNDARIES =
Collections.unmodifiableList(
Arrays.asList(
0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.0, 20.0, 25.0, 30.0, 40.0, 50.0, 65.0, 80.0, 100.0, 130.0, 160.0, 200.0, 250.0,
300.0, 400.0, 500.0, 650.0, 800.0, 1000.0, 2000.0, 5000.0, 10000.0, 20000.0, 50000.0,
100000.0));
static final Aggregation AGGREGATION_WITH_MILLIS_HISTOGRAM =
Distribution.create(BucketBoundaries.create(RPC_MILLIS_BUCKET_BOUNDARIES));
static MeasureDouble QUERY_STATS_ELAPSED =
MeasureDouble.create(
"cloud.google.com/java/spanner/query_stats_elapsed",
"The execution of the query",
MILLISECOND);
// Register the view. It is imperative that this step exists,
// otherwise recorded metrics will be dropped and never exported.
static View QUERY_STATS_LATENCY_VIEW = View
.create(Name.create("cloud.google.com/java/spanner/query_stats_elapsed"),
"The execution of the query",
QUERY_STATS_ELAPSED,
AGGREGATION_WITH_MILLIS_HISTOGRAM,
Collections.emptyList());
static ViewManager manager = Stats.getViewManager();
private static final StatsRecorder STATS_RECORDER = Stats.getStatsRecorder();
static void captureQueryStatsMetric(DatabaseClient dbClient) {
manager.registerView(QUERY_STATS_LATENCY_VIEW);
// Enable OpenCensus exporters to export metrics to Cloud Monitoring.
// Exporters use Application Default Credentials to authenticate.
// See https://developers.google.com/identity/protocols/application-default-credentials
// for more details.
try {
StackdriverStatsExporter.createAndRegister();
} catch (IOException | IllegalStateException e) {
System.out.println("Error during StackdriverStatsExporter");
}
try (ResultSet resultSet = dbClient.singleUse()
.analyzeQuery(Statement.of("SELECT SingerId, AlbumId, AlbumTitle FROM Albums"),
QueryAnalyzeMode.PROFILE)) {
while (resultSet.next()) {
System.out.printf(
"%d %d %s", resultSet.getLong(0), resultSet.getLong(1), resultSet.getString(2));
}
Value value = resultSet.getStats().getQueryStats()
.getFieldsOrDefault("elapsed_time", Value.newBuilder().setStringValue("0 msecs").build());
double elapasedTime = Double.parseDouble(value.getStringValue().replaceAll(" msecs", ""));
STATS_RECORDER.newMeasureMap()
.put(QUERY_STATS_ELAPSED, elapasedTime)
.record();
}
}
Go
import (
"context"
"fmt"
"io"
"strconv"
"strings"
"cloud.google.com/go/spanner"
"google.golang.org/api/iterator"
"contrib.go.opencensus.io/exporter/stackdriver"
"go.opencensus.io/stats"
"go.opencensus.io/stats/view"
"go.opencensus.io/tag"
)
// OpenCensus Tag, Measure and View.
var (
QueryStatsElapsed = stats.Float64("cloud.google.com/go/spanner/query_stats_elapsed",
"The execution of the query", "ms")
QueryStatsLatencyView = view.View{
Name: "cloud.google.com/go/spanner/query_stats_elapsed",
Measure: QueryStatsElapsed,
Description: "The execution of the query",
Aggregation: view.Distribution(0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.0, 20.0, 25.0, 30.0, 40.0, 50.0, 65.0, 80.0, 100.0, 130.0, 160.0, 200.0, 250.0,
300.0, 400.0, 500.0, 650.0, 800.0, 1000.0, 2000.0, 5000.0, 10000.0, 20000.0, 50000.0,
100000.0),
TagKeys: []tag.Key{}}
)
func queryWithQueryStats(w io.Writer, db string) error {
projectID, _, _, err := parseDatabaseName(db)
if err != nil {
return err
}
ctx := context.Background()
client, err := spanner.NewClient(ctx, db)
if err != nil {
return err
}
defer client.Close()
// Register OpenCensus views.
err = view.Register(&QueryStatsLatencyView)
if err != nil {
return err
}
// Create OpenCensus Stackdriver exporter.
sd, err := stackdriver.NewExporter(stackdriver.Options{
ProjectID: projectID,
})
if err != nil {
return err
}
// It is imperative to invoke flush before your main function exits
defer sd.Flush()
// Start the metrics exporter
sd.StartMetricsExporter()
defer sd.StopMetricsExporter()
// Execute a SQL query and get the query stats.
stmt := spanner.Statement{SQL: `SELECT SingerId, AlbumId, AlbumTitle FROM Albums`}
iter := client.Single().QueryWithStats(ctx, stmt)
defer iter.Stop()
for {
row, err := iter.Next()
if err == iterator.Done {
// Record query execution time with OpenCensus.
elapasedTime := iter.QueryStats["elapsed_time"].(string)
elapasedTimeMs, err := strconv.ParseFloat(strings.TrimSuffix(elapasedTime, " msecs"), 64)
if err != nil {
return err
}
stats.Record(ctx, QueryStatsElapsed.M(elapasedTimeMs))
return nil
}
if err != nil {
return err
}
var singerID, albumID int64
var albumTitle string
if err := row.Columns(&singerID, &albumID, &albumTitle); err != nil {
return err
}
fmt.Fprintf(w, "%d %d %s\n", singerID, albumID, albumTitle)
}
}
쿼리 지연 시간 시각화
측정항목을 검색한 후 Cloud Monitoring에서 쿼리 지연 시간을 시각화할 수 있습니다.
다음은 쿼리 지연 시간 측정항목에 대한 5번째 백분위수 지연 시간을 보여주는 그래프의 예시입니다. 백분위수 지연 시간을 50번째 또는 99번째 백분위수로 변경하려면 애그리게이터 메뉴를 사용합니다.
프로그램에서 query_stats_elapsed라는 OpenCensus 뷰를 만듭니다.
이 문자열은 Cloud Monitoring으로 내보낼 때 측정항목 이름의 일부가 됩니다.
다음 단계
