Ctrl+K

Logging

Logging#

Msprime uses the Python logging infrastructure to help debugging complex simulations. Messages at the INFO level are high-level information about the state of the current simulation, such as switches in simulation model, etc. While it is straightforward to set up logging messages using the built-in Python methods, the daiquiri library is a bit more convenient. For example,

import daiquiri
import msprime

daiquiri.setup(level="INFO")
ts = msprime.sim_ancestry(
    10,
    population_size=1000,
    model=[
        msprime.DiscreteTimeWrightFisher(duration=100),
        msprime.StandardCoalescent(),
    ],
    random_seed=1234
)

2024-04-05 14:40:48,154 [2689] INFO     msprime.ancestry: Sampling 10 individuals with ploidy 2 in population 0 (name='pop_0') at time 0

2024-04-05 14:40:48,158 [2689] INFO     msprime.ancestry: Starting replicate 0

2024-04-05 14:40:48,159 [2689] INFO     msprime.ancestry: model[0] {'name': 'dtwf'} started at time=0 nodes=20 edges=0

2024-04-05 14:40:48,159 [2689] INFO     msprime.ancestry: Running model {'name': 'dtwf'} until max time: 100.000000

2024-04-05 14:40:48,162 [2689] INFO     msprime.ancestry: model[1] {'name': 'hudson'} started at time=100 nodes=25 edges=10

2024-04-05 14:40:48,162 [2689] INFO     msprime.ancestry: Running model {'name': 'hudson'} until max time: inf

2024-04-05 14:40:48,163 [2689] INFO     msprime.ancestry: Completed at time=5876.22 nodes=39 edges=38

When running larger simulations and trying to figure out when they might finish, it can be helpful to use the DEBUG logging output. For example:

daiquiri.setup(level="DEBUG")
ts = msprime.sim_ancestry(
    10 ** 5,
    population_size=10000,
    recombination_rate=2e-8,
    sequence_length=1e6,
    random_seed=32
)

2024-04-05 14:40:48,171 [2689] INFO     msprime.ancestry: Sampling 100000 individuals with ploidy 2 in population 0 (name='pop_0') at time 0

2024-04-05 14:40:48,256 [2689] INFO     msprime.ancestry: Starting replicate 0

2024-04-05 14:40:48,265 [2689] INFO     msprime.ancestry: model[0] {'name': 'hudson'} started at time=0 nodes=200000 edges=0

2024-04-05 14:40:48,265 [2689] INFO     msprime.ancestry: Running model {'name': 'hudson'} until max time: inf

2024-04-05 14:40:48,297 [2689] DEBUG    msprime.ancestry: time=0.0104295 ancestors=190080 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,318 [2689] DEBUG    msprime.ancestry: time=0.0219435 ancestors=180166 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,338 [2689] DEBUG    msprime.ancestry: time=0.0346803 ancestors=170256 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,359 [2689] DEBUG    msprime.ancestry: time=0.0491285 ancestors=160336 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,382 [2689] DEBUG    msprime.ancestry: time=0.0657941 ancestors=150418 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,407 [2689] DEBUG    msprime.ancestry: time=0.0847891 ancestors=140540 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,435 [2689] DEBUG    msprime.ancestry: time=0.106283 ancestors=130644 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,466 [2689] DEBUG    msprime.ancestry: time=0.131827 ancestors=120740 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,502 [2689] DEBUG    msprime.ancestry: time=0.161742 ancestors=110874 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,542 [2689] DEBUG    msprime.ancestry: time=0.197291 ancestors=101020 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,587 [2689] DEBUG    msprime.ancestry: time=0.240122 ancestors=91192 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,636 [2689] DEBUG    msprime.ancestry: time=0.293227 ancestors=81390 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,693 [2689] DEBUG    msprime.ancestry: time=0.361519 ancestors=71580 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,760 [2689] DEBUG    msprime.ancestry: time=0.45156 ancestors=61818 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,832 [2689] DEBUG    msprime.ancestry: time=0.573763 ancestors=52074 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:48,912 [2689] DEBUG    msprime.ancestry: time=0.755864 ancestors=42402 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,005 [2689] DEBUG    msprime.ancestry: time=1.03995 ancestors=32814 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,113 [2689] DEBUG    msprime.ancestry: time=1.54834 ancestors=23356 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,245 [2689] DEBUG    msprime.ancestry: time=2.72085 ancestors=14190 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,410 [2689] DEBUG    msprime.ancestry: time=7.38436 ancestors=5736 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,549 [2689] DEBUG    msprime.ancestry: time=150.174 ancestors=558 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,567 [2689] DEBUG    msprime.ancestry: time=4639.98 ancestors=154 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,579 [2689] DEBUG    msprime.ancestry: time=17020.3 ancestors=100 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,588 [2689] DEBUG    msprime.ancestry: time=35240.4 ancestors=96 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,596 [2689] DEBUG    msprime.ancestry: time=66125.6 ancestors=62 ret=ExitReason.MAX_EVENTS

2024-04-05 14:40:49,602 [2689] DEBUG    msprime.ancestry: time=192317 ancestors=0 ret=ExitReason.COALESCENCE

2024-04-05 14:40:49,603 [2689] DEBUG    msprime.ancestry: Skipping remaining 0 models

2024-04-05 14:40:49,696 [2689] INFO     msprime.ancestry: Completed at time=192317 nodes=407802 edges=437129

In this example we run a reasonably large simulation and turn on the DEBUG output. This will then periodically (every 10,000 simulation events) print out the current time in the simulation, and the number of extant ancestral lineages.

Warning

The format of these logging messages is not fixed and may change arbitrarily in the future. If you need to obtain the information within them, please open an issue on GitHub so that we can provide a documented API for this.