# ---
# jupyter:
#   jupytext:
#     text_representation:
#       extension: .py
#       format_name: light
#       format_version: '1.5'
#       jupytext_version: 1.14.4
#   kernelspec:
#     display_name: Python 3.8.5 64-bit
#     metadata:
#       interpreter:
#         hash: 767d51c1340bd893661ea55ea3124f6de3c7a262a8b4abca0554b478b1e2ff90
#     name: python3
# ---

# # Logging and tracing within Deltaflow
#
# In this notebook, we demonstrate methods of logging and tracing of Deltaflow
# graphs while running in the Python Simulator `DeltaPySimulator`.
#
# ## Logging
#
# Let us start with logging techniques first.

# +
import logging

import deltalanguage as dl


# -

# ### Python simulator logging
#
# The first way we can log messages is at the Python Simulator level.
# At this level, we can log the creation of queues and threads, and log each tick of the main thread.
# When the program terminates, or when an error occurs in a node, this is logged as well.
#
# To demonstrate this, below we create a simple graph, consisting of one node which adds
# two integers together and another which saves the result before exiting the program.

# +
@dl.DeltaBlock(allow_const=False)
def add(a: int, b: int) -> int:
    return a + b

s = dl.lib.StateSaver(int, verbose=True)

with dl.DeltaGraph() as graph_1:
    s.save_and_exit(add(2, 3))
# -

# When creating the `DeltaPySimulator`, we can use the `lvl` parameter to specify
# the level at which we display logged messages.
# This can be any integer, but the most common are
# `logging.DEBUG` (10), `logging.INFO` (20), `logging.WARNING` (30) and `logging.ERROR` (40).
# Note that messages logged at higher levels are reported, so a log set at `logging.INFO`
# will include messages from `logging.WARNING` and `logging.ERROR`.
# See Python's [logging levels](https://docs.python.org/3/library/logging.html#logging-levels)
# for further details.
#
# In the example below, we will set our runtime logging level to `logging.INFO`.

# +
rt = dl.DeltaPySimulator(graph_1, lvl=logging.INFO)
rt.run()

assert s.saved == [5]


# -

# ### Logging within an individual node
#
# We can also record computation performed by a single node.
# To do this, we specify the `lvl` argument in decorators `DeltaBlock`, `DeltaMethodBlock`,
# or `Interactive`.
#
# In the example below, we create a new node which adds two integers together,
# but this time we set the logging level to `logging.DEBUG`.

@dl.DeltaBlock(allow_const=False, lvl=logging.DEBUG)
def add_log(a: int, b: int) -> int:
    return a + b


# We can wire up this node the same way as before and see that this time we log what
# messages we send to the `save_and_exit` node.

# +
s = dl.lib.StateSaver(int, verbose=True)

with dl.DeltaGraph() as graph_2:
    s.save_and_exit(add_log(5, 6))

rt = dl.DeltaPySimulator(graph_2)
rt.run()

assert s.saved == [11]


# -

# This same parameter can also be used to log computation in other types of nodes,
# such as method nodes, interactive nodes and even Migen nodes.
#
# ### Logging within a node body
#
# In this next example, we are going to create our own logger and use it within a node's body.
#
# Below we have an interactive node, which will count down and logs each integer it sends.
#
# To log what is happening in this node, we use the `make_logger` command, which will
# create a log for us with a given level and name.
# This is the same command used for logging throughout Deltaflow.

@dl.Interactive(outputs=[('output', int)])
def count_and_log(node):
    logger = dl.make_logger(lvl=logging.DEBUG, name="count_and_log")
    for i in range(10, -1, -1):
        logger.info(f"i= {i}")
        node.send(i)


# We are going to wire this node up to a state saver node again, and this time exit the program once we reach 0.

# +
s = dl.lib.StateSaver(int, condition=lambda x: x == 0, verbose=True)

with dl.DeltaGraph() as graph_3:
    s.save_and_exit_if(count_and_log.call())
# -

# Running this below, we can see the logs from our custom logger.

# +
rt = dl.DeltaPySimulator(graph_3)
rt.run()

assert s.saved == [10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0]
# -

# Note that passing the same name to `make_logger` will return the same logger object.
# This means that other nodes which run multiple times, such as those created by
# `DeltaBlock` or `DeltaMethodBlock` can also use `make_logger` to get the same logger
# each time they're evaluated.
# Note however that this also means if two nodes request a logger with the same name,
# they will both get the same logger.
#
# ### Logging of Messages
#
# The final case we are going to consider is logging messages that are sent between nodes.
#
# For this, we will use a generator, which creates a Deltaflow node for sending each item
# in a list of integers to the next node.

# +
sender = dl.lib.make_generator([5, 4, 3, 2, 1, 0])

s = dl.lib.StateSaver(int, condition=lambda x: x == 0, verbose=True)

with dl.DeltaGraph() as graph_4:
    s.save_and_exit_if(sender.call())
# -

# The `msg_lvl` parameter in `DeltaPySimulator` is used to determine which level logs
# from messages are displayed at.
#
# The messages are logged when the program exits, and are sorted by logical clock order,
# as an aproximation for what time each message was sent.

# +
rt = dl.DeltaPySimulator(graph_4, msg_lvl=logging.INFO)
rt.run()

assert s.saved == [5, 4, 3, 2, 1, 0]
# -

# ## Tracing
#
# You can also use an external tool
# [VizTraser](https://github.com/gaogaotiantian/viztracer)
# for tracing and visualization of `DeltaPySimulator`.
#
# For instance it can be used like this:

# +
from viztracer import VizTracer


# Choose the output file
tracer = VizTracer(output_file="viztracer_example.html")

@dl.DeltaBlock(allow_const=False)
def foo() -> int:
    return 10


@dl.DeltaBlock(in_port_size=5)
def bar(a: int) -> int:
    return a*2


@dl.DeltaBlock()
def adder(a: int, b: int) -> int:
    # For instance add events
    tracer.add_instant("TestEvent", {"a": a, "b": b})
    return a + b


s = dl.lib.StateSaver(int, verbose=True)

with dl.DeltaGraph() as graph:
    foo_out = foo()
    bar_out = bar(foo_out)
    s.save_and_exit(adder(foo_out, bar_out))


# Choose which part of the code you wish to trace
tracer.start()
rt = dl.DeltaPySimulator(graph)
rt.run()
tracer.stop()

# Uncomment to save the HTML report
# tracer.save()

assert s.saved == [30]
# -

# To save the report just uncomment the corresponding line; after that
# it can be opened with your favourite browser and investigated in detail.
# We have already saved an example report for this graph and attached it to the tutorial.
#
# Note that the argument `in_port_size` defines how many messages can be stored in the
# incoming queues of `bar`.
# This information is used by the simulator to make sure that all threads are executed in turn,
# i.e. if the queue is full then the node filling it will be paused and another node will be
# processed.
#
# Try to generate tracing reports with other values of `in_port_size` and look for any changes in behaviour.
# Note however that the result of the simulation is independent of this as well as any delays
# in the graph thus we say that this graph is correct.
#
# Please refer to the VizTraser [docs](https://viztracer.readthedocs.io/) to learn about many more
# features it supports.
# We find it especially useful to integrate with loggers and trace custom events.
#
# ## Summary
#
# Python has an enormous ecosystems of tools that can suit the need of developers
# to debug and profile multithreaded or multiprocessed simulations on the fly.
#
# We've presented a selection of our logging techniques as well as the external tool VizTraser.
# The aim of this is to show that with Deltaflow you can:
# - debug the program before and during its execution
# - find performance bottlenecks
# - prepare the program for Deltasimulator and Deltaruntime

StarcoderdataJupyterScriptsDedupFiltered