Skip to content

Commit c0016de

Browse files
PhongChuongPhongChuong
authored
chore: restore RequestProfilerTest.java that was mistakenly deleted (#2592)
Add RequestProfilerTest.java again as it was accidentally deleted cloud-java-bot because: 1. [PR#2589](https://togithub.com/googleapis/java-bigquerystorage/pull/2589) to exclude RequestProfilerTest.java has not taken affect 2. RequestProfilerTest.java was deleted again after the approval and then merged
1 parent 4177e4b commit c0016de

1 file changed

Lines changed: 215 additions & 0 deletions

File tree

‎google-cloud-bigquerystorage/src/test/java/com/google/cloud/bigquery/storage/v1/RequestProfilerTest.java‎

Lines changed: 215 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,215 @@
1+
/*
2+
* Copyright 2024 Google LLC
3+
*
4+
* Licensed under the Apache License, Version 2.0 (the "License");
5+
* you may not use this file except in compliance with the License.
6+
* You may obtain a copy of the License at
7+
*
8+
* https://www.apache.org/licenses/LICENSE-2.0
9+
*
10+
* Unless required by applicable law or agreed to in writing, software
11+
* distributed under the License is distributed on an "AS IS" BASIS,
12+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
* See the License for the specific language governing permissions and
14+
* limitations under the License.
15+
*/
16+
package com.google.cloud.bigquery.storage.v1;
17+
18+
import static org.junit.Assert.assertTrue;
19+
20+
import com.google.cloud.bigquery.storage.v1.RequestProfiler.OperationName;
21+
import com.google.common.collect.ImmutableSet;
22+
import com.google.common.util.concurrent.ListeningExecutorService;
23+
import com.google.common.util.concurrent.MoreExecutors;
24+
import com.google.common.util.concurrent.ThreadFactoryBuilder;
25+
import java.util.ArrayList;
26+
import java.util.List;
27+
import java.util.concurrent.Executors;
28+
import java.util.concurrent.Future;
29+
import java.util.concurrent.TimeUnit;
30+
import java.util.logging.Logger;
31+
import org.junit.After;
32+
import org.junit.Before;
33+
import org.junit.Test;
34+
import org.junit.runner.RunWith;
35+
import org.junit.runners.JUnit4;
36+
37+
@RunWith(JUnit4.class)
38+
public class RequestProfilerTest {
39+
private static final Logger log = Logger.getLogger(RequestProfiler.class.getName());
40+
41+
private RequestProfiler.RequestProfilerHook profilerHook =
42+
new RequestProfiler.RequestProfilerHook(true);
43+
44+
@Before
45+
public void setup() {
46+
RequestProfiler.disableAndResetProfiler();
47+
profilerHook.enableProfiler();
48+
}
49+
50+
@After
51+
public void close() {
52+
RequestProfiler.disableAndResetProfiler();
53+
}
54+
55+
@Test
56+
public void testNormalCase() throws Exception {
57+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, "request_1");
58+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_1");
59+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_1");
60+
profilerHook.startOperation(OperationName.RESPONSE_LATENCY, "request_1");
61+
62+
// Another request starts in the middle
63+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, "request_2");
64+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_2");
65+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_2");
66+
67+
// Continue request 1
68+
profilerHook.endOperation(OperationName.RESPONSE_LATENCY, "request_1");
69+
70+
// Continue request 2
71+
profilerHook.startOperation(OperationName.RESPONSE_LATENCY, "request_2");
72+
profilerHook.endOperation(OperationName.RESPONSE_LATENCY, "request_2");
73+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, "request_2");
74+
75+
// Continue request 1
76+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, "request_1");
77+
78+
// Test the report generated.
79+
String reportText = profilerHook.flushAndGenerateReportText();
80+
log.info(reportText);
81+
assertTrue(reportText.contains("Request uuid: request_1 with total time"));
82+
assertTrue(reportText.contains("Operation name json_to_proto_conversion starts at"));
83+
assertTrue(reportText.contains("Operation name response_latency starts at"));
84+
assertTrue(reportText.contains("Request uuid: request_2 with total time"));
85+
86+
// Second time flush is called, it should generate empty report.
87+
reportText = profilerHook.flushAndGenerateReportText();
88+
assertTrue(reportText.contains("0 requests finished during"));
89+
}
90+
91+
@Test
92+
public void mixFinishedAndUnfinishedRequest() throws Exception {
93+
// Start request 1.
94+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, "request_1");
95+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_1");
96+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_1");
97+
profilerHook.startOperation(OperationName.RESPONSE_LATENCY, "request_1");
98+
99+
// Another request starts in the middle
100+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, "request_2");
101+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, "request_2");
102+
103+
// First report should be empty since no requests end.
104+
String reportText = profilerHook.flushAndGenerateReportText();
105+
assertTrue(reportText.contains("0 requests finished during"));
106+
107+
// End one of them.
108+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, "request_1");
109+
reportText = profilerHook.flushAndGenerateReportText();
110+
assertTrue(reportText.contains("Request uuid: request_1 with total time"));
111+
112+
// End another, expect the first request's log not showing up.
113+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, "request_2");
114+
reportText = profilerHook.flushAndGenerateReportText();
115+
assertTrue(!reportText.contains("Request uuid: request_1 with total time"));
116+
assertTrue(reportText.contains("Request uuid: request_2 with total time"));
117+
118+
// Flush again will be empty report.
119+
reportText = profilerHook.flushAndGenerateReportText();
120+
assertTrue(reportText.contains("0 requests finished during"));
121+
}
122+
123+
@Test
124+
public void concurrentProfilingTest_1000ReqsRunTogether() throws Exception {
125+
int totalRequest = 1000;
126+
ListeningExecutorService threadPool =
127+
MoreExecutors.listeningDecorator(
128+
Executors.newCachedThreadPool(
129+
new ThreadFactoryBuilder().setDaemon(true).setNameFormat("TestThread").build()));
130+
131+
List<Future<?>> futures = new ArrayList<>();
132+
// Make some request particularly slower than the others.
133+
ImmutableSet<Integer> slowRequestIndex = ImmutableSet.of(10, 15, 20, 25, 30, 40, 50);
134+
for (int i = 0; i < totalRequest; i++) {
135+
int finalI = i;
136+
futures.add(
137+
threadPool.submit(
138+
() -> {
139+
String uuid = String.format("request_%s", finalI);
140+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, uuid);
141+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
142+
if (slowRequestIndex.contains(finalI)) {
143+
try {
144+
TimeUnit.MILLISECONDS.sleep(finalI * 100);
145+
} catch (InterruptedException e) {
146+
throw new RuntimeException(e);
147+
}
148+
}
149+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
150+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
151+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
152+
profilerHook.startOperation(OperationName.WAIT_QUEUE, uuid);
153+
profilerHook.endOperation(OperationName.WAIT_QUEUE, uuid);
154+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, uuid);
155+
}));
156+
}
157+
158+
// Wait all requests to finish.
159+
for (int i = 0; i < futures.size(); i++) {
160+
futures.get(i).get();
161+
}
162+
String reportText = profilerHook.flushAndGenerateReportText();
163+
assertTrue(reportText.contains("During the last 60000 milliseconds at system time"));
164+
assertTrue(reportText.contains("in total 1000 requests finished"));
165+
assertTrue(reportText.contains("Request uuid: request_50 with total time"));
166+
assertTrue(reportText.contains("Request uuid: request_40 with total time"));
167+
assertTrue(reportText.contains("Request uuid: request_30 with total time"));
168+
assertTrue(reportText.contains("Request uuid: request_25 with total time"));
169+
assertTrue(reportText.contains("Request uuid: request_20 with total time"));
170+
}
171+
172+
@Test
173+
public void concurrentProfilingTest_RunWhileFlushing() throws Exception {
174+
int totalRequest = 1000;
175+
ListeningExecutorService threadPool =
176+
MoreExecutors.listeningDecorator(
177+
Executors.newCachedThreadPool(
178+
new ThreadFactoryBuilder().setDaemon(true).setNameFormat("TestThread").build()));
179+
180+
List<Future<?>> futures = new ArrayList<>();
181+
// Make some request particularly slower than the others.
182+
ImmutableSet<Integer> slowRequestIndex = ImmutableSet.of(10, 15, 20, 25, 30, 40, 50);
183+
for (int i = 0; i < totalRequest; i++) {
184+
int finalI = i;
185+
futures.add(
186+
threadPool.submit(
187+
() -> {
188+
try {
189+
String uuid = String.format("request_%s", finalI);
190+
profilerHook.startOperation(OperationName.TOTAL_LATENCY, uuid);
191+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
192+
if (slowRequestIndex.contains(finalI)) {
193+
TimeUnit.MILLISECONDS.sleep(finalI * 100);
194+
}
195+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
196+
profilerHook.startOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
197+
profilerHook.endOperation(OperationName.JSON_TO_PROTO_CONVERSION, uuid);
198+
profilerHook.startOperation(OperationName.WAIT_QUEUE, uuid);
199+
profilerHook.endOperation(OperationName.WAIT_QUEUE, uuid);
200+
profilerHook.endOperation(OperationName.TOTAL_LATENCY, uuid);
201+
String unused = profilerHook.flushAndGenerateReportText();
202+
} catch (InterruptedException e) {
203+
throw new RuntimeException(e);
204+
}
205+
}));
206+
}
207+
208+
// Wait all requests to finish.
209+
for (int i = 0; i < futures.size(); i++) {
210+
futures.get(i).get();
211+
}
212+
String reportText = profilerHook.flushAndGenerateReportText();
213+
assertTrue(reportText.contains("0 requests finished during"));
214+
}
215+
}

0 commit comments

Comments
 (0)