xref: /6.0.3/phosphor/tests/library/macro_test.cc (revision 195e116e)
1/* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2/*
3 *     Copyright 2016 Couchbase, Inc
4 *
5 *   Licensed under the Apache License, Version 2.0 (the "License");
6 *   you may not use this file except in compliance with the License.
7 *   You may obtain a copy of the License at
8 *
9 *       http://www.apache.org/licenses/LICENSE-2.0
10 *
11 *   Unless required by applicable law or agreed to in writing, software
12 *   distributed under the License is distributed on an "AS IS" BASIS,
13 *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 *   See the License for the specific language governing permissions and
15 *   limitations under the License.
16 */
17
18#include <functional>
19#include <vector>
20
21#include <gmock/gmock.h>
22#include <gtest/gtest.h>
23
24#include <phosphor/phosphor.h>
25
26/*
27 * The MacroTraceEventTest class is used to test that macros behave as
28 * expected. That when called they will trace events and that from a
29 * single thread they will be appropriately ordered.
30 *
31 * The class contains a vector of functions `verifications`, which should be
32 * added to from a testcase. This vector of functions will be called on each
33 * event in the buffer in order and is used to verify that the event appears
34 * as it should (has the right category/name/type/arguments).
35 */
36class MacroTraceEventTest : public testing::Test {
37public:
38    MacroTraceEventTest() {
39        PHOSPHOR_INSTANCE.start(
40                phosphor::TraceConfig(phosphor::BufferMode::fixed,
41                                      sizeof(phosphor::TraceChunk))
42                        .setCategories({{"category"}, {"ex*"}},
43                                       {{"excluded"}}));
44    }
45
46    ~MacroTraceEventTest() {
47        PHOSPHOR_INSTANCE.stop();
48        auto buffer = PHOSPHOR_INSTANCE.getBuffer();
49        auto event = buffer->begin();
50        auto verification = verifications.begin();
51
52        while(event != buffer->end() && verification != verifications.end()) {
53            (*verification)(*event);
54            ++event;
55            ++verification;
56        }
57
58        EXPECT_EQ(buffer->end(), event) << "Too many events in buffer!";
59        EXPECT_EQ(verifications.end(), verification)
60                            << "Too many verifications left ("
61                            << std::distance(verification,
62                                             verifications.end()) << ")";
63    }
64
65protected:
66    std::vector<std::function<void(const phosphor::TraceEvent&)>> verifications;
67};
68
69class MockUniqueLock : std::unique_lock<std::mutex> {
70public:
71    MOCK_METHOD0(lock, void());
72    MOCK_METHOD0(unlock, void());
73};
74
75TEST_F(MacroTraceEventTest, Synchronous) {
76    TRACE_EVENT_START0("category", "name");
77    verifications.emplace_back([](const phosphor::TraceEvent& event) {
78        EXPECT_STREQ("name", event.getName());
79        EXPECT_STREQ("category", event.getCategory());
80        EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
81    });
82    TRACE_EVENT_END0("category", "name");
83    verifications.emplace_back([](const phosphor::TraceEvent& event) {
84        EXPECT_STREQ("name", event.getName());
85        EXPECT_STREQ("category", event.getCategory());
86        EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
87    });
88    TRACE_EVENT_START("category", "name", 3, 4);
89    verifications.emplace_back([](const phosphor::TraceEvent& event) {
90        EXPECT_STREQ("name", event.getName());
91        EXPECT_STREQ("category", event.getCategory());
92        EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
93        EXPECT_EQ(3, event.getArgs()[0].as_int);
94        EXPECT_EQ(4, event.getArgs()[1].as_int);
95    });
96    TRACE_EVENT_END("category", "name", 5, 6);
97    verifications.emplace_back([](const phosphor::TraceEvent& event) {
98        EXPECT_STREQ("name", event.getName());
99        EXPECT_STREQ("category", event.getCategory());
100        EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
101        EXPECT_EQ(5, event.getArgs()[0].as_int);
102        EXPECT_EQ(6, event.getArgs()[1].as_int);
103    });
104    TRACE_EVENT_START1("category", "name", "my_arg1", 3);
105    verifications.emplace_back([](const phosphor::TraceEvent& event) {
106        EXPECT_STREQ("name", event.getName());
107        EXPECT_STREQ("category", event.getCategory());
108        EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
109        EXPECT_EQ(3, event.getArgs()[0].as_int);
110        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
111    });
112    TRACE_EVENT_END1("category", "name", "my_arg1", 3);
113    verifications.emplace_back([](const phosphor::TraceEvent& event) {
114        EXPECT_STREQ("name", event.getName());
115        EXPECT_STREQ("category", event.getCategory());
116        EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
117        EXPECT_EQ(3, event.getArgs()[0].as_int);
118        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
119    });
120    TRACE_EVENT_START2("category", "name", "my_arg1", 3, "my_arg2", 4);
121    verifications.emplace_back([](const phosphor::TraceEvent& event) {
122        EXPECT_STREQ("name", event.getName());
123        EXPECT_STREQ("category", event.getCategory());
124        EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
125        EXPECT_EQ(3, event.getArgs()[0].as_int);
126        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
127        EXPECT_EQ(4, event.getArgs()[1].as_int);
128        EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
129    });
130    TRACE_EVENT_END2("category", "name", "my_arg1", 3, "my_arg2", 4);
131    verifications.emplace_back([](const phosphor::TraceEvent& event) {
132        EXPECT_STREQ("name", event.getName());
133        EXPECT_STREQ("category", event.getCategory());
134        EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
135        EXPECT_EQ(3, event.getArgs()[0].as_int);
136        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
137        EXPECT_EQ(4, event.getArgs()[1].as_int);
138        EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
139    });
140}
141
142TEST_F(MacroTraceEventTest, Asynchronous) {
143    TRACE_ASYNC_START0("category", "name", 3);
144    verifications.emplace_back([](const phosphor::TraceEvent& event) {
145        EXPECT_STREQ("name", event.getName());
146        EXPECT_STREQ("category", event.getCategory());
147        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncStart, event.getType());
148        EXPECT_EQ(3, event.getArgs()[0].as_int);
149        EXPECT_STREQ("id", event.getArgNames()[0]);
150    });
151    TRACE_ASYNC_END0("category", "name", 5);
152    verifications.emplace_back([](const phosphor::TraceEvent& event) {
153        EXPECT_STREQ("name", event.getName());
154        EXPECT_STREQ("category", event.getCategory());
155        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncEnd, event.getType());
156        EXPECT_EQ(5, event.getArgs()[0].as_int);
157        EXPECT_STREQ("id_end", event.getArgNames()[0]);
158    });
159    TRACE_ASYNC_START("category", "name", 3, 4);
160    verifications.emplace_back([](const phosphor::TraceEvent& event) {
161        EXPECT_STREQ("name", event.getName());
162        EXPECT_STREQ("category", event.getCategory());
163        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncStart, event.getType());
164        EXPECT_EQ(3, event.getArgs()[0].as_int);
165        EXPECT_EQ(4, event.getArgs()[1].as_int);
166        EXPECT_STREQ("id", event.getArgNames()[0]);
167    });
168    TRACE_ASYNC_END("category", "name", 5, 6);
169    verifications.emplace_back([](const phosphor::TraceEvent& event) {
170        EXPECT_STREQ("name", event.getName());
171        EXPECT_STREQ("category", event.getCategory());
172        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncEnd, event.getType());
173        EXPECT_EQ(5, event.getArgs()[0].as_int);
174        EXPECT_EQ(6, event.getArgs()[1].as_int);
175        EXPECT_STREQ("id_end", event.getArgNames()[0]);
176    });
177    TRACE_ASYNC_START1("category", "name", 3, "my_arg1", 4);
178    verifications.emplace_back([](const phosphor::TraceEvent& event) {
179        EXPECT_STREQ("name", event.getName());
180        EXPECT_STREQ("category", event.getCategory());
181        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncStart, event.getType());
182        EXPECT_EQ(3, event.getArgs()[0].as_int);
183        EXPECT_STREQ("id", event.getArgNames()[0]);
184        EXPECT_EQ(4, event.getArgs()[1].as_int);
185        EXPECT_STREQ("my_arg1", event.getArgNames()[1]);
186    });
187    TRACE_ASYNC_END1("category", "name", 3, "my_arg1", 4);
188    verifications.emplace_back([](const phosphor::TraceEvent& event) {
189        EXPECT_STREQ("name", event.getName());
190        EXPECT_STREQ("category", event.getCategory());
191        EXPECT_EQ(phosphor::TraceEvent::Type::AsyncEnd, event.getType());
192        EXPECT_EQ(3, event.getArgs()[0].as_int);
193        EXPECT_STREQ("id_end", event.getArgNames()[0]);
194        EXPECT_EQ(4, event.getArgs()[1].as_int);
195        EXPECT_STREQ("my_arg1", event.getArgNames()[1]);
196    });
197}
198
199TEST_F(MacroTraceEventTest, Instant) {
200    TRACE_INSTANT0("category", "name");
201    verifications.emplace_back([](const phosphor::TraceEvent& event) {
202        EXPECT_STREQ("name", event.getName());
203        EXPECT_STREQ("category", event.getCategory());
204        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
205    });
206    TRACE_INSTANT("category", "name", 3, 4);
207    verifications.emplace_back([](const phosphor::TraceEvent& event) {
208        EXPECT_STREQ("name", event.getName());
209        EXPECT_STREQ("category", event.getCategory());
210        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
211        EXPECT_EQ(3, event.getArgs()[0].as_int);
212        EXPECT_EQ(4, event.getArgs()[1].as_int);
213    });
214    TRACE_INSTANT1("category", "name", "my_arg1", 3);
215    verifications.emplace_back([](const phosphor::TraceEvent& event) {
216        EXPECT_STREQ("name", event.getName());
217        EXPECT_STREQ("category", event.getCategory());
218        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
219        EXPECT_EQ(3, event.getArgs()[0].as_int);
220        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
221    });
222    TRACE_INSTANT2("category", "name", "my_arg1", 3, "my_arg2", 4);
223    verifications.emplace_back([](const phosphor::TraceEvent& event) {
224        EXPECT_STREQ("name", event.getName());
225        EXPECT_STREQ("category", event.getCategory());
226        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
227        EXPECT_EQ(3, event.getArgs()[0].as_int);
228        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
229        EXPECT_EQ(4, event.getArgs()[1].as_int);
230        EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
231    });
232}
233
234TEST_F(MacroTraceEventTest, Global) {
235    TRACE_GLOBAL0("category", "name");
236    verifications.emplace_back([](const phosphor::TraceEvent& event) {
237        EXPECT_STREQ("name", event.getName());
238        EXPECT_STREQ("category", event.getCategory());
239        EXPECT_EQ(phosphor::TraceEvent::Type::GlobalInstant, event.getType());
240    });
241    TRACE_GLOBAL("category", "name", 3, 4);
242    verifications.emplace_back([](const phosphor::TraceEvent& event) {
243        EXPECT_STREQ("name", event.getName());
244        EXPECT_STREQ("category", event.getCategory());
245        EXPECT_EQ(phosphor::TraceEvent::Type::GlobalInstant, event.getType());
246        EXPECT_EQ(3, event.getArgs()[0].as_int);
247        EXPECT_EQ(4, event.getArgs()[1].as_int);
248    });
249    TRACE_GLOBAL1("category", "name", "my_arg1", 3);
250    verifications.emplace_back([](const phosphor::TraceEvent& event) {
251        EXPECT_STREQ("name", event.getName());
252        EXPECT_STREQ("category", event.getCategory());
253        EXPECT_EQ(phosphor::TraceEvent::Type::GlobalInstant, event.getType());
254        EXPECT_EQ(3, event.getArgs()[0].as_int);
255        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
256    });
257    TRACE_GLOBAL2("category", "name", "my_arg1", 3, "my_arg2", 4);
258    verifications.emplace_back([](const phosphor::TraceEvent& event) {
259        EXPECT_STREQ("name", event.getName());
260        EXPECT_STREQ("category", event.getCategory());
261        EXPECT_EQ(phosphor::TraceEvent::Type::GlobalInstant, event.getType());
262        EXPECT_EQ(3, event.getArgs()[0].as_int);
263        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
264        EXPECT_EQ(4, event.getArgs()[1].as_int);
265        EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
266    });
267}
268
269TEST_F(MacroTraceEventTest, Scoped) {
270    {
271        TRACE_EVENT0("category", "name");
272        verifications.emplace_back([](const phosphor::TraceEvent &event) {
273            EXPECT_STREQ("name", event.getName());
274            EXPECT_STREQ("category", event.getCategory());
275            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
276        });
277    }
278    {
279        TRACE_EVENT1("category", "name", "my_arg1", 3);
280        verifications.emplace_back([](const phosphor::TraceEvent &event) {
281            EXPECT_STREQ("name", event.getName());
282            EXPECT_STREQ("category", event.getCategory());
283            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
284            EXPECT_EQ(3, event.getArgs()[0].as_int);
285            EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
286        });
287    }
288    {
289        TRACE_EVENT2("category", "name", "my_arg1", 3, "my_arg2", 4);
290        verifications.emplace_back([](const phosphor::TraceEvent &event) {
291            EXPECT_STREQ("name", event.getName());
292            EXPECT_STREQ("category", event.getCategory());
293            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
294            EXPECT_EQ(3, event.getArgs()[0].as_int);
295            EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
296            EXPECT_EQ(4, event.getArgs()[1].as_int);
297            EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
298        });
299    }
300    {
301        testing::InSequence dummy;
302        MockUniqueLock m;
303        EXPECT_CALL(m, lock()).Times(1);
304        EXPECT_CALL(m, unlock()).Times(1);
305        TRACE_LOCKGUARD(m, "category", "name");
306        verifications.emplace_back([](const phosphor::TraceEvent& event) {
307            EXPECT_STREQ("name.acquire", event.getName());
308            EXPECT_STREQ("category", event.getCategory());
309            EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
310        });
311        verifications.emplace_back([](const phosphor::TraceEvent& event) {
312            EXPECT_STREQ("name.acquire", event.getName());
313            EXPECT_STREQ("category", event.getCategory());
314            EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
315        });
316        verifications.emplace_back([](const phosphor::TraceEvent& event) {
317            EXPECT_STREQ("name.held", event.getName());
318            EXPECT_STREQ("category", event.getCategory());
319            EXPECT_EQ(phosphor::TraceEvent::Type::SyncStart, event.getType());
320        });
321        verifications.emplace_back([](const phosphor::TraceEvent& event) {
322            EXPECT_STREQ("name.held", event.getName());
323            EXPECT_STREQ("category", event.getCategory());
324            EXPECT_EQ(phosphor::TraceEvent::Type::SyncEnd, event.getType());
325        });
326    }
327}
328
329void macro_test_functionA() {
330    TRACE_FUNCTION0("category");
331}
332
333void macro_test_functionC() {
334    TRACE_FUNCTION1("category", "my_arg1", 3);
335}
336
337void macro_test_functionD() {
338    TRACE_FUNCTION2("category", "my_arg1", 3, "my_arg2", 4);
339}
340
341TEST_F(MacroTraceEventTest, Function) {
342    {
343        macro_test_functionA();
344        verifications.emplace_back([](const phosphor::TraceEvent &event) {
345            EXPECT_STREQ("macro_test_functionA", event.getName());
346            EXPECT_STREQ("category", event.getCategory());
347            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
348        });
349    }
350    {
351        macro_test_functionC();
352        verifications.emplace_back([](const phosphor::TraceEvent &event) {
353            EXPECT_STREQ("macro_test_functionC", event.getName());
354            EXPECT_STREQ("category", event.getCategory());
355            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
356            EXPECT_EQ(3, event.getArgs()[0].as_int);
357            EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
358        });
359    }
360    {
361        macro_test_functionD();
362        verifications.emplace_back([](const phosphor::TraceEvent &event) {
363            EXPECT_STREQ("macro_test_functionD", event.getName());
364            EXPECT_STREQ("category", event.getCategory());
365            EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
366            EXPECT_EQ(3, event.getArgs()[0].as_int);
367            EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
368            EXPECT_EQ(4, event.getArgs()[1].as_int);
369            EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
370        });
371    }
372}
373
374TEST_F(MacroTraceEventTest, Complete) {
375    int variable = 4;
376    const auto start = std::chrono::steady_clock::now();
377    const auto end = start + std::chrono::microseconds(1);
378    TRACE_COMPLETE0("category", "name", start, end);
379    verifications.emplace_back([](const phosphor::TraceEvent& event) {
380        EXPECT_STREQ("name", event.getName());
381        EXPECT_STREQ("category", event.getCategory());
382        EXPECT_EQ(1000, event.getDuration());
383        EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
384    });
385
386    TRACE_COMPLETE("category", "name", start, end, 3, variable);
387    verifications.emplace_back([](const phosphor::TraceEvent& event) {
388        EXPECT_STREQ("name", event.getName());
389        EXPECT_STREQ("category", event.getCategory());
390        EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
391        EXPECT_EQ(1000, event.getDuration());
392        EXPECT_EQ(3, event.getArgs()[0].as_int);
393        EXPECT_EQ(4, event.getArgs()[1].as_int);
394    });
395
396    TRACE_COMPLETE1("category", "name", start, end, "my_arg1", 3);
397    verifications.emplace_back([](const phosphor::TraceEvent& event) {
398        EXPECT_STREQ("name", event.getName());
399        EXPECT_STREQ("category", event.getCategory());
400        EXPECT_EQ(1000, event.getDuration());
401        EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
402        EXPECT_EQ(3, event.getArgs()[0].as_int);
403        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
404    });
405
406    TRACE_COMPLETE2(
407            "category", "name", start, end, "my_arg1", 3, "my_arg2", variable);
408    verifications.emplace_back([](const phosphor::TraceEvent& event) {
409        EXPECT_STREQ("name", event.getName());
410        EXPECT_STREQ("category", event.getCategory());
411        EXPECT_EQ(1000, event.getDuration());
412        EXPECT_EQ(phosphor::TraceEvent::Type::Complete, event.getType());
413        EXPECT_EQ(3, event.getArgs()[0].as_int);
414        EXPECT_STREQ("my_arg1", event.getArgNames()[0]);
415        EXPECT_EQ(4, event.getArgs()[1].as_int);
416        EXPECT_STREQ("my_arg2", event.getArgNames()[1]);
417    });
418}
419
420TEST_F(MacroTraceEventTest, InlineString) {
421    TRACE_INSTANT("category", "name", PHOSPHOR_INLINE_STR("Hello, World!"));
422    verifications.emplace_back([](const phosphor::TraceEvent& event) {
423        EXPECT_STREQ("name", event.getName());
424        EXPECT_STREQ("category", event.getCategory());
425        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
426        EXPECT_EQ("Hello, W",
427                  std::string(event.getArgs()[0].as_istring));
428    });
429    TRACE_INSTANT("category", "name", PHOSPHOR_INLINE_STR("Hello"));
430    verifications.emplace_back([](const phosphor::TraceEvent& event) {
431        EXPECT_STREQ("name", event.getName());
432        EXPECT_STREQ("category", event.getCategory());
433        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
434        EXPECT_EQ("Hello",
435                  std::string(event.getArgs()[0].as_istring));
436    });
437    TRACE_INSTANT("category", "name", PHOSPHOR_INLINE_STR(""));
438    verifications.emplace_back([](const phosphor::TraceEvent& event) {
439        EXPECT_STREQ("name", event.getName());
440        EXPECT_STREQ("category", event.getCategory());
441        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
442        EXPECT_EQ("",
443                  std::string(event.getArgs()[0].as_istring));
444    });
445}
446
447// Basic smoke test that category filtering works at a macro level,
448// other unit tests should handle the more extensive testing
449TEST_F(MacroTraceEventTest, CategoryFiltering) {
450    TRACE_INSTANT0("excluded", "name");
451    TRACE_INSTANT0("example", "name");
452    verifications.emplace_back([](const phosphor::TraceEvent& event) {
453        EXPECT_STREQ("name", event.getName());
454        EXPECT_STREQ("example", event.getCategory());
455        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
456    });
457    TRACE_INSTANT("excluded", "name", 3, 4);
458    TRACE_INSTANT("example", "name", 3, 4);
459    verifications.emplace_back([](const phosphor::TraceEvent& event) {
460        EXPECT_STREQ("name", event.getName());
461        EXPECT_STREQ("example", event.getCategory());
462        EXPECT_EQ(phosphor::TraceEvent::Type::Instant, event.getType());
463        EXPECT_EQ(3, event.getArgs()[0].as_int);
464        EXPECT_EQ(4, event.getArgs()[1].as_int);
465    });
466}
467