1import unittest
2
3from parser.tracker import Tracker, AppPhase
4from parser.aggregate import aggregate_times
5
6class TestStats(unittest.TestCase):
7  def setUp(self):
8    self.app_phase = AppPhase()
9    self.tracker1 = Tracker(1, False, self.app_phase)
10    self.tracker2 = Tracker(2, True, self.app_phase)
11    self.timevars = dict()
12    for t in range(0, 20):
13      name = "t" + str(t)
14      self.timevars[name] = self.from_spectime(name)
15
16  def from_spectime(self, spectime):
17      return 10 ** int(spectime[1:])
18
19  def feed_spec_text(self, text):
20    for line in text.split("\n"):
21      line = line.lstrip().rstrip()
22      if line == "":
23        continue
24      time, _, *mark = line.split(":")
25      mark = ":".join(mark)
26      mark = mark.replace("<thread", "").replace(">", "")
27      if mark[2:3] == "1":
28        self.tracker1.handle_mark(self.from_spectime(time), mark)
29      else:
30        self.tracker2.handle_mark(self.from_spectime(time), mark)
31    self.times, self.self_times, self.has_warmup_and_benchmark, _ = aggregate_times(
32        dict(t1=self.tracker1, t2=self.tracker2),
33        special_case_lr_pe=False)
34
35  def check_overall_time(self, tag, spec_interval, app_phase=None):
36    expected = eval(spec_interval, {}, self.timevars) * 1000.0
37    layer, phase = tag.split("_")
38    if not app_phase:
39      actual = self.times[phase][layer]
40    else:
41      actual = self.times[app_phase][phase][layer]
42    self.assertAlmostEqual(expected, actual, places=1,
43                           msg="\n".join([
44                               self.tracker1.debugstring,
45                               str(self.times)]))
46
47  def check_self_time(self, tag, spec_interval):
48    expected = eval(spec_interval, {}, self.timevars) * 1000.0
49    layer, phase = tag.split("_")
50    actual = self.self_times[phase][layer]
51    self.assertAlmostEqual(expected, actual, places=1,
52                           msg=self.tracker1.debugstring)
53
54  def test_baseline(self):
55    spec = """
56    t0: tracing_mark_write:B|<thread1>|[NN_LR_PP]funcP
57    t1: tracing_mark_write:E|<thread1>
58    """
59    self.feed_spec_text(spec)
60    self.check_overall_time("LR_PP", "(t1-t0)")
61
62  def test_local_call_to_other_layer(self):
63    spec = """
64    t0: tracing_mark_write:B|<thread1>|[NN_LA_PP]funcE1
65    t1: tracing_mark_write:B|<thread1>|[NN_LR_PP]funcC1
66    t2: tracing_mark_write:E|<thread1>
67    t3: tracing_mark_write:E|<thread1>
68    """
69    self.feed_spec_text(spec)
70    self.check_overall_time("LA_PP", "(t3-t0)")
71    self.check_overall_time("LR_PP", "(t2-t1)")
72    self.check_self_time("LA_PP", "(t3-t0) - (t2-t1)")
73
74  def test_local_call_to_other_layer_wrong_nesting(self):
75    spec = """
76    t0: tracing_mark_write:B|<thread1>|[NN_LR_PP]funcE1
77    t1: tracing_mark_write:B|<thread1>|[NN_LA_PP]funcC1
78    t2: tracing_mark_write:E|<thread1>
79    t3: tracing_mark_write:E|<thread1>
80    """
81    with self.assertRaises(Exception) as ctx:
82      self.feed_spec_text(spec)
83
84  def test_switch_phase_during_execution(self):
85    spec = """
86    t0: tracing_mark_write:B|<thread1>|[NN_LC_PTR]funcC1
87    t1: tracing_mark_write:B|<thread1>|[SW][NN_LC_PCO]funcC1
88    t2: tracing_mark_write:E|<thread1>
89    t3: tracing_mark_write:E|<thread1>
90    """
91    self.feed_spec_text(spec)
92    self.check_overall_time("LC_PTR", "(t1-t0)")
93    self.check_overall_time("LC_PCO", "(t2-t1)")
94
95  def test_subphases(self):
96    spec = """
97    t0: tracing_mark_write:B|<thread1>|[NN_LR_PE]funcR2
98    t1: tracing_mark_write:B|<thread1>|[NN_LC_PCO]funcC2
99    t2: tracing_mark_write:E|<thread1>
100    t3: tracing_mark_write:E|<thread1>
101    """
102    self.feed_spec_text(spec)
103    self.check_overall_time("LC_PCO", "(t2-t1)")
104    self.check_overall_time("LC_PE", "(t2-t1)")
105    self.check_overall_time("LR_PE", "(t3-t0)")
106    self.check_self_time("LC_PCO", "(t2-t1)")
107    self.check_self_time("LR_PE", "(t3-t0)-(t2-t1)")
108
109  def test_subphases_nested(self):
110    spec = """
111    t0: tracing_mark_write:B|<thread1>|[NN_LR_PE]funcR2
112    t1: tracing_mark_write:B|<thread1>|[NN_LC_PCO]funcC2
113    t2: tracing_mark_write:B|<thread1>|[NN_LC_PCO]funcC2A
114    t3: tracing_mark_write:E|<thread1>
115    t4: tracing_mark_write:E|<thread1>
116    t5: tracing_mark_write:E|<thread1>
117    """
118    self.feed_spec_text(spec)
119    self.check_overall_time("LC_PCO", "(t4-t1)")
120    self.check_overall_time("LC_PE", "(t4-t1)")
121    self.check_overall_time("LR_PE", "(t5-t0)")
122    self.check_self_time("LR_PE", "(t5-t0)-(t4-t1)")
123
124  def test_subphases_la_pr(self):
125    spec = """
126    t0: tracing_mark_write:B|<thread1>|[NN_LA_PE]lape
127    t1: tracing_mark_write:B|<thread1>|[NN_LA_PR]lapr
128    t2: tracing_mark_write:E|<thread1>
129    t3: tracing_mark_write:E|<thread1>
130    """
131    self.feed_spec_text(spec)
132    self.check_overall_time("LA_PE", "(t3-t0)")
133    self.check_overall_time("LA_PR", "(t2-t1)")
134    self.check_self_time("LA_PE", "(t3-t0)")
135    self.check_self_time("LA_PR", "(t2-t1)")
136
137  def test_subphases_and_layers(self):
138    spec = """
139    t0: tracing_mark_write:B|<thread1>|[NN_LA_PE]pe
140    t1: tracing_mark_write:B|<thread1>|[NN_LR_PE]pe
141    t2: tracing_mark_write:B|<thread1>|[NN_LR_PIO]pio
142    t3: tracing_mark_write:B|<thread1>|[NN_LI_PIO]pio
143    t4: tracing_mark_write:E|<thread1>
144    t5: tracing_mark_write:E|<thread1>
145    t6: tracing_mark_write:E|<thread1>
146    t7: tracing_mark_write:E|<thread1>
147    """
148    self.feed_spec_text(spec)
149    self.check_overall_time("LR_PIO", "(t5-t2)")
150    self.check_overall_time("LI_PIO", "(t4-t3)")
151    self.check_overall_time("LI_PE", "(t4-t3)")
152    self.check_overall_time("LA_PE", "(t7-t0)")
153    self.check_overall_time("LR_PE", "(t6-t1)")
154
155  def test_additional_detail_in_same_layer(self):
156    spec = """
157    t0: tracing_mark_write:B|<thread1>|[NN_LR_PE]funcR3
158    t1: tracing_mark_write:B|<thread1>|[NN_LR_PE]funcR4
159    t2: tracing_mark_write:E|<thread1>
160    t3: tracing_mark_write:E|<thread1>
161    """
162    self.feed_spec_text(spec)
163    self.check_overall_time("LR_PE", "(t3-t0)")
164    self.check_self_time("LR_PE", "(t3-t0)")
165
166  def test_synchronous_ipc_call(self):
167    spec = """
168    t0: tracing_mark_write:B|<thread1>|[NN_LR_PC]funcR5
169    t1: tracing_mark_write:B|<thread1>|[NN_LI_PI]getCapabilities
170    t2: tracing_mark_write:B|<thread1>|HIDL::IDevice::getCapabilities::client
171    t3: tracing_mark_write:E|<thread1>
172    t4: tracing_mark_write:E|<thread1>
173    t5: tracing_mark_write:E|<thread1>
174    """
175    self.feed_spec_text(spec)
176    self.check_overall_time("LR_PC", "(t5-t0)-(t4-t1)")
177    self.check_overall_time("LI_PI", "(t4-t1)")
178    self.check_self_time("LR_PC", "(t5-t0)-(t4-t1)")
179
180  def test_async_ipc_call_waited_synchronously(self):
181    spec = """
182    t0: tracing_mark_write:B|<thread1>|[NN_LI_PC]prepareModel
183    t1: tracing_mark_write:B|<thread1>|HIDL::IDevice::prepareModel_1_1::client
184    t2: tracing_mark_write:B|<thread2>|HIDL::IDevice::prepareModel_1_1::server
185    t3: tracing_mark_write:B|<thread2>|[NN_LD_PC]SampleDriver::prepareModel
186    t4: tracing_mark_write:B|<thread2>|HIDL::IPreparedModelCallback::notify::client
187    t5: tracing_mark_write:E|<thread2>
188    t5: tracing_mark_write:E|<thread2>
189    t6: tracing_mark_write:E|<thread2>
190    t7: tracing_mark_write:B|<thread1>|HIDL::IPreparedModelCallback::notify::server
191    t8: tracing_mark_write:E|<thread1>
192    t9: tracing_mark_write:E|<thread1>
193    t10: tracing_mark_write:E|<thread1>
194    """
195    self.feed_spec_text(spec)
196    self.check_overall_time("LI_PC", "(t10-t0)")
197    self.check_overall_time("LD_PC", "(t6-t2)")
198
199  def test_subtracting_time_direct_descendant(self):
200    spec = """
201    t0: tracing_mark_write:B|<thread1>|[NN_LI_PC]prepareModel
202    t1: tracing_mark_write:B|<thread1>|[SUB][NN_LR_PC]VersionedIDevice::prepareM
203    t2: tracing_mark_write:E|<thread1>
204    t3: tracing_mark_write:E|<thread1>
205    """
206    self.feed_spec_text(spec)
207    self.check_overall_time("LI_PC", "(t3-t0)-(t2-t1)")
208    self.check_overall_time("LR_PC", "(t2-t1)")
209
210  def test_subtracting_time_nested(self):
211    spec = """
212    t0: tracing_mark_write:B|<thread1>|[NN_LI_PC]prepareModel
213    t1: tracing_mark_write:B|<thread1>|[NN_LI_PC]foo
214    t2: tracing_mark_write:B|<thread1>|[SUB][NN_LR_PC]VersionedIDevice::prepareM
215    t3: tracing_mark_write:E|<thread1>
216    t4: tracing_mark_write:E|<thread1>
217    t5: tracing_mark_write:E|<thread1>
218    """
219    self.feed_spec_text(spec)
220    self.check_overall_time("LI_PC", "(t5-t0)-(t3-t2)")
221    self.check_overall_time("LR_PC", "(t3-t2)")
222
223
224  def test_onetime_initialization_simple(self):
225    spec = """
226    t0: tracing_mark_write:B|<thread1>|[NN_LR_PP]funcR5
227    t1: tracing_mark_write:B|<thread1>|[NN_LR_PI]funcI
228    t2: tracing_mark_write:E|<thread1>
229    t3: tracing_mark_write:E|<thread1>
230    """
231    self.feed_spec_text(spec)
232    self.check_overall_time("LR_PI", "(t2-t1)")
233    self.check_overall_time("LR_PP", "(t3-t0)-(t2-t1)")
234
235  def test_utility_code(self):
236    spec = """
237    t0: tracing_mark_write:B|<thread1>|[NN_LR_PP]funcR6
238    t1: tracing_mark_write:B|<thread1>|[NN_LU_PU]funcU
239    t2: tracing_mark_write:E|<thread1>
240    t3: tracing_mark_write:E|<thread1>
241    """
242    self.feed_spec_text(spec)
243    self.check_overall_time("LR_PP", "(t3-t0)")
244
245  def test_app_layer(self):
246    spec = """
247    t0: tracing_mark_write:B|<thread1>|[NN_LA_PO]po
248    t1: tracing_mark_write:B|<thread1>|[NN_LA_PP]pp
249    t2: tracing_mark_write:B|<thread1>|[SW][NN_LA_PC]pc
250    t3: tracing_mark_write:E|<thread1>
251    t4: tracing_mark_write:E|<thread1>
252    t5: tracing_mark_write:E|<thread1>
253    """
254    self.feed_spec_text(spec)
255    self.check_overall_time("LA_PO", "(t5-t0)")
256    self.check_overall_time("LA_PP", "(t2-t1)")
257    self.check_overall_time("LA_PC", "(t3-t2)")
258
259  def test_app_not_using_PT(self):
260    spec = """
261    t0: tracing_mark_write:B|<thread1>|[NN_LA_PC]pc
262    t1: tracing_mark_write:B|<thread1>|[NN_LR_PC]pc
263    t2: tracing_mark_write:E|<thread1>
264    t3: tracing_mark_write:B|<thread1>|[NN_LR_PT]pt
265    t4: tracing_mark_write:E|<thread1>
266    t5: tracing_mark_write:E|<thread1>
267    """
268    self.feed_spec_text(spec)
269    self.check_overall_time("LA_PC", "(t5-t0)-(t4-t3)")
270    self.check_overall_time("LR_PC", "(t2-t1)")
271    self.check_overall_time("LR_PT", "(t4-t3)")
272
273  def test_warmup_and_benchmark(self):
274    spec = """
275    t0: tracing_mark_write:B|<thread1>|[NN_LA_PWU]pwu
276    t1: tracing_mark_write:B|<thread1>|[NN_LR_PE]ANeuralNetworksExecution_create
277    t2: tracing_mark_write:E|<thread1>
278    t3: tracing_mark_write:E|<thread1>
279    t4: tracing_mark_write:B|<thread1>|[NN_LA_PBM]pbm
280    t5: tracing_mark_write:B|<thread1>|[NN_LR_PE]ANeuralNetworksExecution_create
281    t6: tracing_mark_write:E|<thread1>
282    t7: tracing_mark_write:E|<thread1>
283    """
284    self.feed_spec_text(spec)
285    self.check_overall_time("LR_PE", "(t2-t1)+(t6-t5)")
286    self.check_overall_time("LR_PE", "(t2-t1)", "PWU")
287    self.check_overall_time("LR_PE", "(t6-t5)", "PBM")
288