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-09-07 21:34:29,047 [2304] INFO msprime.ancestry: Sampling 10 individuals with ploidy 2 in population 0 (name='pop_0') at time 0
2024-09-07 21:34:29,050 [2304] INFO msprime.ancestry: Starting replicate 0
2024-09-07 21:34:29,050 [2304] INFO msprime.ancestry: model[0] {'name': 'dtwf'} started at time=0 nodes=20 edges=0
2024-09-07 21:34:29,051 [2304] INFO msprime.ancestry: Running model {'name': 'dtwf'} until max time: 100.000000
2024-09-07 21:34:29,053 [2304] INFO msprime.ancestry: model[1] {'name': 'hudson'} started at time=100 nodes=25 edges=10
2024-09-07 21:34:29,053 [2304] INFO msprime.ancestry: Running model {'name': 'hudson'} until max time: inf
2024-09-07 21:34:29,054 [2304] 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-09-07 21:34:29,061 [2304] INFO msprime.ancestry: Sampling 100000 individuals with ploidy 2 in population 0 (name='pop_0') at time 0
2024-09-07 21:34:29,151 [2304] INFO msprime.ancestry: Starting replicate 0
2024-09-07 21:34:29,157 [2304] INFO msprime.ancestry: model[0] {'name': 'hudson'} started at time=0 nodes=200000 edges=0
2024-09-07 21:34:29,158 [2304] INFO msprime.ancestry: Running model {'name': 'hudson'} until max time: inf
2024-09-07 21:34:29,194 [2304] DEBUG msprime.ancestry: time=0.0104295 ancestors=190080 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,220 [2304] DEBUG msprime.ancestry: time=0.0219435 ancestors=180166 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,246 [2304] DEBUG msprime.ancestry: time=0.0346803 ancestors=170256 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,275 [2304] DEBUG msprime.ancestry: time=0.0491285 ancestors=160336 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,306 [2304] DEBUG msprime.ancestry: time=0.0657941 ancestors=150418 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,339 [2304] DEBUG msprime.ancestry: time=0.0847891 ancestors=140540 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,376 [2304] DEBUG msprime.ancestry: time=0.106283 ancestors=130644 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,414 [2304] DEBUG msprime.ancestry: time=0.131827 ancestors=120740 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,457 [2304] DEBUG msprime.ancestry: time=0.161742 ancestors=110874 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,504 [2304] DEBUG msprime.ancestry: time=0.197291 ancestors=101020 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,557 [2304] DEBUG msprime.ancestry: time=0.240122 ancestors=91192 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,615 [2304] DEBUG msprime.ancestry: time=0.293227 ancestors=81390 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,680 [2304] DEBUG msprime.ancestry: time=0.361519 ancestors=71580 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,755 [2304] DEBUG msprime.ancestry: time=0.45156 ancestors=61818 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,833 [2304] DEBUG msprime.ancestry: time=0.573763 ancestors=52074 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:29,922 [2304] DEBUG msprime.ancestry: time=0.755864 ancestors=42402 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,024 [2304] DEBUG msprime.ancestry: time=1.03995 ancestors=32814 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,141 [2304] DEBUG msprime.ancestry: time=1.54834 ancestors=23356 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,282 [2304] DEBUG msprime.ancestry: time=2.72085 ancestors=14190 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,467 [2304] DEBUG msprime.ancestry: time=7.38436 ancestors=5736 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,620 [2304] DEBUG msprime.ancestry: time=150.174 ancestors=558 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,639 [2304] DEBUG msprime.ancestry: time=4639.98 ancestors=154 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,652 [2304] DEBUG msprime.ancestry: time=17020.3 ancestors=100 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,661 [2304] DEBUG msprime.ancestry: time=35240.4 ancestors=96 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,669 [2304] DEBUG msprime.ancestry: time=66125.6 ancestors=62 ret=ExitReason.MAX_EVENTS
2024-09-07 21:34:30,675 [2304] DEBUG msprime.ancestry: time=192317 ancestors=0 ret=ExitReason.COALESCENCE
2024-09-07 21:34:30,676 [2304] DEBUG msprime.ancestry: Skipping remaining 0 models
2024-09-07 21:34:30,772 [2304] 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.