Coverage for pyTooling/Tracing/__init_

1# ==================================================================================================================== #

2# _____ _ _ _____ _ #

3# _ __ _ |_ _|__ ___ | (_)_ __ __ _|_ _| __ __ _ ___(_)_ __ __ _ #

4# | '_ \| | | || |/ _ \ / _ \| | | '_ \ / _` | | || '__/ _` |/ __| | '_ \ / _` | #

5# | |_) | |_| || | (_) | (_) | | | | | | (_| |_| || | | (_| | (__| | | | | (_| | #

6# | .__/ \__, ||_|\___/ \___/|_|_|_| |_|\__, (_)_||_| \__,_|\___|_|_| |_|\__, | #

7# |_| |___/ |___/ |___/ #

8# ==================================================================================================================== #

9# Authors: #

10# Patrick Lehmann #

11# #

12# License: #

13# ==================================================================================================================== #

15# #

16# Licensed under the Apache License, Version 2.0 (the "License"); #

17# you may not use this file except in compliance with the License. #

18# You may obtain a copy of the License at #

19# #

20# http://www.apache.org/licenses/LICENSE-2.0 #

21# #

22# Unless required by applicable law or agreed to in writing, software #

23# distributed under the License is distributed on an "AS IS" BASIS, #

24# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. #

25# See the License for the specific language governing permissions and #

26# limitations under the License. #

27# #

28# SPDX-License-Identifier: Apache-2.0 #

29# ==================================================================================================================== #

30#

31"""

32Tools for software execution tracing.

34.. seealso::

36 :mod:`pyTooling.Stopwatch`

37 |rarr| A single measurement instead of nested timespans.

38 :mod:`pyTooling.Tree`

39 |rarr| The tree data structure spans and their sub-spans form.

40"""

41from __future__ import annotations

43from datetime import datetime

44from time import perf_counter_ns

45from threading import local

46from types import TracebackType

47from typing import Optional as Nullable, Iterator, Self, Iterable, Any

49from pyTooling.Decorators import export, readonly

50from pyTooling.MetaClasses import ExtendedType

51from pyTooling.Exceptions import ToolingException

52from pyTooling.Common import getFullyQualifiedName

55__all__ = ["_threadLocalData"]

57_threadLocalData = local()

58"""A reference to the thread local data needed by the pyTooling.Tracing classes."""

61@export

62class TracingException(ToolingException):

63 """Base-exception of all exceptions raised by :mod:`pyTooling.Tracing`."""

66@export

67class Event(metaclass=ExtendedType, slots=True):

68 """

69 Represents a named event within a timespan (:class:`Span`) used in a software execution trace.

71 It may contain arbitrary attributes (key-value pairs).

72 """

73 _name: str #: Name of the event.

74 _parent: Nullable[Span] #: Reference to the parent span.

75 _time: Nullable[datetime] #: Timestamp of the event.

76 _dict: dict[str, Any] #: Dictionary of associated attributes.

78 def __init__(self, name: str, time: Nullable[datetime] = None, parent: Nullable[Span] = None) -> None:

79 """

80 Initializes a named event.

82 :param name: The name of the event.

83 :param time: Optional, time when the event happened.

84 :param parent: Optional, reference to the parent span.

85 :raises ValueError: If parameter 'name' is empty.

86 :raises TypeError: If parameter 'parent' is not of type :class:`Span`.

87 """

88 if isinstance(name, str): 88 ↛ 94line 88 didn't jump to line 94 because the condition on line 88 was always true

89 if name == "": 89 ↛ 90line 89 didn't jump to line 90 because the condition on line 89 was never true

90 raise ValueError(f"Parameter 'name' is empty.")

92 self._name = name

93 else:

94 ex = TypeError("Parameter 'name' is not of type 'str'.")

95 ex.add_note(f"Got type '{getFullyQualifiedName(name)}'.")

96 raise ex

98 if time is None: 98 ↛ 100line 98 didn't jump to line 100 because the condition on line 98 was always true

99 self._time = None

100 elif isinstance(time, datetime):

101 self._time = time

102 else:

103 ex = TypeError("Parameter 'time' is not of type 'datetime'.")

104 ex.add_note(f"Got type '{getFullyQualifiedName(time)}'.")

105 raise ex

106

107 if parent is None:

108 self._parent = None

109 elif isinstance(parent, Span): 109 ↛ 113line 109 didn't jump to line 113 because the condition on line 109 was always true

110 self._parent = parent

111 parent._events.append(self)

112 else:

113 ex = TypeError("Parameter 'parent' is not of type 'Span'.")

114 ex.add_note(f"Got type '{getFullyQualifiedName(parent)}'.")

115 raise ex

116

117 self._dict = {}

118

119 @readonly

120 def Name(self) -> str:

121 """

122 Read-only property to access the event's name.

123

124 :returns: Name of the event.

125 """

126 return self._name

127

128 @readonly

129 def Time(self) -> datetime:

130 """

131 Read-only property to access the event's timestamp.

132

133 :returns: Timestamp of the event.

134 """

135 return self._time

136

137 @readonly

138 def Parent(self) -> Nullable[Span]:

139 """

140 Read-only property to access the event's parent span.

141

142 :returns: Parent span.

143 """

144 return self._parent

145

146 def __getitem__(self, key: str) -> Any:

147 """

148 Read an event's attached attributes (key-value-pairs) by key.

149

150 :param key: The key to look for.

151 :returns: The value associated to the given key.

152 """

153 return self._dict[key]

154

155 def __setitem__(self, key: str, value: Any) -> None:

156 """

157 Create or update an event's attached attributes (key-value-pairs) by key.

158

159 If a key doesn't exist yet, a new key-value-pair is created.

160

161 :param key: The key to create or update.

162 :param value: The value to associate to the given key.

163 """

164 self._dict[key] = value

165

166 def __delitem__(self, key: str) -> None:

167 """

168 Remove an entry from event's attached attributes (key-value-pairs) by key.

169

170 :param key: The key to remove.

171 :raises KeyError: If key doesn't exist in the event's attributes.

172 """

173 del self._dict[key]

174

175 def __contains__(self, key: str) -> bool:

176 """

177 Checks if the key is an attached attribute (key-value-pairs) on this event.

178

179 :param key: The key to check.

180 :returns: ``True``, if the key is an attached attribute.

181 """

182 return key in self._dict

183

184 def __iter__(self) -> Iterator[tuple[str, Any]]:

185 """

186 Returns an iterator to iterate all associated attributes of this event as :pycode:`(key, value)` tuples.

187

188 :returns: Iterator to iterate all attributes.

189 """

190 return iter(self._dict.items())

191

192 def __len__(self) -> int:

193 """

194 Returns the number of attached attributes (key-value-pairs) on this event.

195

196 :returns: Number of attached attributes.

197 """

198 return len(self._dict)

199

200 def __str__(self) -> str:

201 """

202 Return a string representation of the event.

203

204 :returns: The event's name.

205 """

206 return self._name

207

208

209@export

210class Span(metaclass=ExtendedType, slots=True):

211 """

212 Represents a timespan (span) within another timespan or trace.

213

214 It may contain sub-spans, events and arbitrary attributes (key-value pairs).

215 """

216 _name: str #: Name of the timespan

217 _parent: Nullable[Span] #: Reference to the parent span (or trace).

218

219 _beginTime: Nullable[datetime] #: Timestamp when the timespan begins.

220 _endTime: Nullable[datetime] #: Timestamp when the timespan ends.

221 _startTime: Nullable[int] #: Performance counter in ns when the timespan was started.

222 _stopTime: Nullable[int] #: Performance counter in ns when the timespan was stopped.

223 _totalTime: Nullable[int] #: Duration of this timespan in ns.

224

225 _spans: list[Span] #: Sub-timespans

226 _events: list[Event] #: Events happened within this timespan

227 _dict: dict[str, Any] #: Dictionary of associated attributes.

228

229 def __init__(self, name: str, parent: Nullable[Span] = None) -> None:

230 """

231 Initializes a timespan as part of a software execution trace.

232

233 :param name: Name of the timespan.

234 :param parent: Optional, reference to a parent span or trace.

235 :raises ValueError: If parameter 'name' is empty.

236 :raises TypeError: If parameter 'parent' is not of type :class:`Span`.

237 """

238 if isinstance(name, str): 238 ↛ 244line 238 didn't jump to line 244 because the condition on line 238 was always true

239 if name == "": 239 ↛ 240line 239 didn't jump to line 240 because the condition on line 239 was never true

240 raise ValueError(f"Parameter 'name' is empty.")

241

242 self._name = name

243 else:

244 ex = TypeError("Parameter 'name' is not of type 'str'.")

245 ex.add_note(f"Got type '{getFullyQualifiedName(parent)}'.")

246 raise ex

247

248 if parent is None:

249 self._parent = None

250 elif isinstance(parent, Span): 250 ↛ 254line 250 didn't jump to line 254 because the condition on line 250 was always true

251 self._parent = parent

252 parent._spans.append(self)

253 else:

254 ex = TypeError("Parameter 'parent' is not of type 'Span'.")

255 ex.add_note(f"Got type '{getFullyQualifiedName(parent)}'.")

256 raise ex

257

258 self._beginTime = None

259 self._startTime = None

260 self._endTime = None

261 self._stopTime = None

262 self._totalTime = None

263

264 self._spans = []

265 self._events = []

266 self._dict = {}

267

268 @readonly

269 def Name(self) -> str:

270 """

271 Read-only property to access the timespan's name.

272

273 :returns: Name of the timespan.

274 """

275 return self._name

276

277 @readonly

278 def Parent(self) -> Nullable[Span]:

279 """

280 Read-only property to access the span's parent span or trace.

281

282 :returns: Parent span.

283 """

284 return self._parent

285

286 def _AddSpan(self, span: Span) -> Self:

287 """

288 Append a sub-span to this timespan and set this timespan as its parent.

289

290 :param span: The sub-span to append.

291 :returns: The appended sub-span.

292 """

293 self._spans.append(span)

294 span._parent = self

295

296 return span

297

298 @readonly

299 def HasSubSpans(self) -> bool:

300 """

301 Check if this timespan contains nested sub-spans.

302

303 :returns: ``True``, if the span has nested spans.

304 """

305 return len(self._spans) > 0

306

307 @readonly

308 def SubSpanCount(self) -> int:

309 """

310 Return the number of sub-spans within this span.

311

312 :returns: Number of nested spans.

313 """

314 return len(self._spans)

315

316 # iterate subspans with optional predicate

317 def IterateSubSpans(self) -> Iterator[Span]:

318 """

319 Returns an iterator to iterate all nested sub-spans.

320

321 :returns: Iterator to iterate all sub-spans.

322 """

323 return iter(self._spans)

324

325 @readonly

326 def HasEvents(self) -> bool:

327 """

328 Check if this timespan contains events.

329

330 :returns: ``True``, if the span has events.

331 """

332 return len(self._events) > 0

333

334 @readonly

335 def EventCount(self) -> int:

336 """

337 Return the number of events within this span.

338

339 :returns: Number of events.

340 """

341 return len(self._events)

342

343 # iterate events with optional predicate

344 def IterateEvents(self) -> Iterator[Event]:

345 """

346 Returns an iterator to iterate all embedded events.

347

348 :returns: Iterator to iterate all events.

349 """

350 return iter(self._events)

351

352 @readonly

353 def StartTime(self) -> Nullable[datetime]:

354 """

355 Read-only property accessing the absolute time when the span was started.

356

357 :returns: The time when the span was entered, otherwise None.

358 """

359 return self._beginTime

360

361 @readonly

362 def StopTime(self) -> Nullable[datetime]:

363 """

364 Read-only property accessing the absolute time when the span was stopped.

365

366 :returns: The time when the span was exited, otherwise None.

367 """

368 return self._endTime

369

370 @readonly

371 def Duration(self) -> float:

372 """

373 Read-only property accessing the duration from start operation to stop operation.

374

375 If the span is not yet stopped, the duration from start to now is returned.

376

377 :returns: Duration since span was started in seconds.

378 :raises TracingException: When span was never started.

379 """

380 if self._startTime is None:

381 raise TracingException(f"{self.__class__.__name__} was never started.")

382

383 return ((perf_counter_ns() - self._startTime) if self._stopTime is None else self._totalTime) / 1e9

384

385 @classmethod

386 def CurrentSpan(cls) -> Span:

387 """

388 Class-method to return the currently active timespan (span) or ``None``.

389

390 :returns: Currently active span or ``None``.

391 """

392 global _threadLocalData

393

394 try:

395 currentSpan = _threadLocalData.currentSpan

396 except AttributeError:

397 currentSpan = None

398

399 return currentSpan

400

401 def __enter__(self) -> Self:

402 """

403 Implementation of the :ref:`context manager protocol's <context-managers>` ``__enter__(...)`` method.

404

405 A span will be started.

406

407 :returns: The span itself.

408 :raises TracingException: If no trace is active, so the span has nothing to attach to. |br|

409 Use a with-statement on :class:`Trace` to set up software execution tracing.

410 """

411 global _threadLocalData

412

413 try:

414 currentSpan = _threadLocalData.currentSpan

415 except AttributeError:

416 ex = TracingException("Can't setup span. No active trace.")

417 ex.add_note("Use with-statement using 'Trace()' to setup software execution tracing.")

418 raise ex

419

420 _threadLocalData.currentSpan = currentSpan._AddSpan(self)

421

422 self._beginTime = datetime.now()

423 self._startTime = perf_counter_ns()

424

425 return self

426

427 def __exit__(

428 self,

429 exc_type: Nullable[type[BaseException]] = None,

430 exc_val: Nullable[BaseException] = None,

431 exc_tb: Nullable[TracebackType] = None

432 ) -> Nullable[bool]:

433 """

434 Implementation of the :ref:`context manager protocol's <context-managers>` ``__exit__(...)`` method.

435

436 An active span will be stopped.

437

438 Exit the context and ......

439

440 :param exc_type: Exception type

441 :param exc_val: Exception instance

442 :param exc_tb: Exception's traceback.

443 :returns: ``None``

444 """

445 global _threadLocalData

446

447 self._stopTime = perf_counter_ns()

448 self._endTime = datetime.now()

449 self._totalTime = self._stopTime - self._startTime

450

451 currentSpan = _threadLocalData.currentSpan

452 _threadLocalData.currentSpan = currentSpan._parent

453

454 def __getitem__(self, key: str) -> Any:

455 """

456 Read an event's attached attributes (key-value-pairs) by key.

457

458 :param key: The key to look for.

459 :returns: The value associated to the given key.

460 """

461 return self._dict[key]

462

463 def __setitem__(self, key: str, value: Any) -> None:

464 """

465 Create or update an event's attached attributes (key-value-pairs) by key.

466

467 If a key doesn't exist yet, a new key-value-pair is created.

468

469 :param key: The key to create or update.

470 :param value: The value to associate to the given key.

471 """

472 self._dict[key] = value

473

474 def __delitem__(self, key: str) -> None:

475 """

476 Remove an entry from event's attached attributes (key-value-pairs) by key.

477

478 :param key: The key to remove.

479 :raises KeyError: If key doesn't exist in the event's attributes.

480 """

481 del self._dict[key]

482

483 def __contains__(self, key: str) -> bool:

484 """

485 Checks if the key is an attached attribute (key-value-pairs) on this event.

486

487 :param key: The key to check.

488 :returns: ``True``, if the key is an attached attribute.

489 """

490 return key in self._dict

491

492 def __iter__(self) -> Iterator[tuple[str, Any]]:

493 """

494 Returns an iterator to iterate all associated attributes of this timespan as :pycode:`(key, value)` tuples.

495

496 :returns: Iterator to iterate all attributes.

497 """

498 return iter(self._dict.items())

499

500 def __len__(self) -> int:

501 """

502 Returns the number of attached attributes (key-value-pairs) on this event.

503

504 :returns: Number of attached attributes.

505 """

506 return len(self._dict)

507

508 def Format(self, indent: int = 1, columnSize: int = 25) -> Iterable[str]:

509 """

510 Render this timespan and its sub-spans as indented lines.

511

512 :param indent: Optional, indentation level of this timespan.

513 :param columnSize: Optional, column the durations are aligned at.

514 :returns: One line per timespan, deepest last.

515 """

516 result = []

517 result.append(f"{' ' * indent}🕑{self._name:<{columnSize - 2 * indent}} {self._totalTime/1e6:8.3f} ms")

518 for span in self._spans:

519 result.extend(span.Format(indent + 1, columnSize))

520

521 return result

522

523 def __repr__(self) -> str:

524 """

525 Return a detailed string representation of this timespan.

526

527 :returns: The timespan's name, followed by its parents up to the trace.

528 """

529 return f"{self._name} -> {self._parent!r}"

530

531 def __str__(self) -> str:

532 """

533 Return a string representation of the timespan.

534

535 :returns: The span's name.

536 """

537 return self._name

538

539

540@export

541class Trace(Span):

542 """

543 Represents a software execution trace made up of timespans (:class:`Span`).

544

545 The trace is the top-most element in a tree of timespans. All timespans share the same *TraceID*, thus even in a

546 distributed software execution, timespans can be aggregated with delay in a centralized database and the flow of

547 execution can be reassembled by grouping all timespans with same *TraceID*. Execution order can be derived from

548 timestamps and parallel execution is represented by overlapping timespans sharing the same parent *SpanID*. Thus, the

549 tree structure can be reassembled by inspecting the parent *SpanID* relations within the same *TraceID*.

550

551 A trace may contain sub-spans, events and arbitrary attributes (key-value pairs).

552 """

553

554 def __init__(self, name: str) -> None:

555 """

556 Initializes a software execution trace.

557

558 :param name: Name of the trace.

559 """

560 super().__init__(name)

561

562 def __enter__(self) -> Self:

563 """

564 Start the trace and register it as the current trace and current span of this thread.

565

566 :returns: The trace itself, so it can be named in an ``as`` clause.

567 """

568 global _threadLocalData

569

570 # TODO: check if a trace is already setup

571 # try:

572 # currentTrace = _threadLocalData.currentTrace

573 # except AttributeError:

574 # pass

575

576 _threadLocalData.currentTrace = self

577 _threadLocalData.currentSpan = self

578

579 self._beginTime = datetime.now()

580 self._startTime = perf_counter_ns()

581

582 return self

583

584 def __exit__(

585 self,

586 exc_type: Nullable[type[BaseException]] = None,

587 exc_val: Nullable[BaseException] = None,

588 exc_tb: Nullable[TracebackType] = None

589 ) -> Nullable[bool]:

590 """

591 Exit the context and ......

592

593 :param exc_type: Exception type

594 :param exc_val: Exception instance

595 :param exc_tb: Exception's traceback.

596 :returns: ``None``

597 """

598 global _threadLocalData

599

600 self._stopTime = perf_counter_ns()

601 self._endTime = datetime.now()

602 self._totalTime = self._stopTime - self._startTime

603

604 del _threadLocalData.currentTrace

605 del _threadLocalData.currentSpan

606

607 return None

608

609 @classmethod

610 def CurrentTrace(cls) -> Trace:

611 """

612 Class-method to return the currently active trace or ``None``.

613

614 :returns: Currently active trace or ``None``.

615 """

616 try:

617 currentTrace = _threadLocalData.currentTrace

618 except AttributeError:

619 currentTrace = None

620

621 return currentTrace

622

623 def Format(self, indent: int = 0, columnSize: int = 25) -> Iterable[str]:

624 """

625 Render this trace and its spans as indented lines.

626

627 :param indent: Optional, indentation level of the trace.

628 :param columnSize: Optional, column the durations are aligned at.

629 :returns: A headline, followed by one line per timespan.

630 """

631 result = []

632 result.append(f"{' ' * indent}Software Execution Trace: {self._totalTime/1e6:8.3f} ms")

633 result.append(f"{' ' * indent}📉{self._name:<{columnSize - 2}} {self._totalTime/1e6:8.3f} ms")

634 for span in self._spans:

635 result.extend(span.Format(indent + 1, columnSize - 2))

636

637 return result

Coverage for pyTooling/Tracing/init.py: 85%

218 statements