Process Monitoring with TotalDepth.common.process
¶
TotalDepth.common.process
can monitor the memory and CPU usage of a running process.
It does this by creating a thread which, at regular intervals, reports process data to the log file in JSON.
The basic use is like this:
from TotalDepth.common import process
with process.log_process(1.0):
# Your code here
Then TotalDepth.common.process
will write process data as a single line in the log file every 1.0 seconds.
The JSON data is preceded by the following, recognisable, entry in the log file:
2019-10-31 14:10:06,051 - process.py - 86611 - (ProcMon ) - INFO - ProcessLoggingThread-JSON
The JSON data looks like this example (but on one line):
{
"timestamp": "2019-10-31 14:10:06.051630",
"memory_info":
{
"rss": 11939840,
"vms": 4404228096,
"pfaults": 531770,
"pageins": 0
},
"cpu_times": {
"user": 0.583945792,
"system": 0.66087648,
"children_user": 0.0,
"children_system": 0.0
},
"elapsed_time": 12.42771601676941
}
Command Line Tools¶
Command line tools can add process
capability with an argument parser created by TotalDepth.common.cmn_cmd_opts
arg_parser()
:
process.add_process_logger_to_argument_parser(parser)
This makes the --log-process
option available which takes a numeric value as a float in seconds (default zero which means no process logging) for the logging interval.
Your code pattern is then:
args = parser.parse_args()
if args.log_process > 0.0:
with process.log_process(args.log_process):
# Do something
Plotting the Data¶
TotalDepth.common.process
can be used from the command line to extract the data from the log file and plot it with Gnuplot.
Example¶
Here we will create eight large, randomly sized strings and simulate doing some work:
import random
import time
from TotalDepth.common import process
with process.log_process(0.1):
for i in range(8):
size = random.randint(128, 128 + 256) * 1024 ** 2
s = ' ' * (size)
# Simulate 0.5 to 1.5 seconds of work.
time.sleep(0.5 + random.random())
del s
# Simulate 0.25 to 0.75 seconds of work.
time.sleep(0.25 + random.random() / 2)
This will produce a log such as:
2019-10-31 14:09:53,726 - process.py - 86611 - (ProcMon ) - INFO - ProcessLoggingThread-JSON {"timestamp": "2019-10-31 14:09:53.726676", "memory_info": {"rss": 11898880, "vms": 4404228096, "pfaults": 3624, "pageins": 0}, "cpu_times": {"user": 0.07540488, "system": 0.020255324, "children_user": 0.0, "children_system": 0.0}, "elapsed_time": 0.10263395309448242}
2019-10-31 14:09:53,896 - process.py - 86611 - (ProcMon ) - INFO - ProcessLoggingThread-JSON {"timestamp": "2019-10-31 14:09:53.896083", "memory_info": {"rss": 162922496, "vms": 4555227136, "pfaults": 40495, "pageins": 0}, "cpu_times": {"user": 0.108017992, "system": 0.056484236, "children_user": 0.0, "children_system": 0.0}, "elapsed_time": 0.27210497856140137}
2019-10-31 14:09:53,997 - process.py - 86611 - (ProcMon ) - INFO - ProcessLoggingThread-JSON {"timestamp": "2019-10-31 14:09:53.996930", "memory_info": {"rss": 162930688, "vms": 4555227136, "pfaults": 40497, "pageins": 0}, "cpu_times": {"user": 0.10846144, "system": 0.05655662, "children_user": 0.0, "children_system": 0.0}, "elapsed_time": 0.373028039932251}
...
2019-10-31 14:10:06,051 - process.py - 86611 - (ProcMon ) - INFO - ProcessLoggingThread-JSON {"timestamp": "2019-10-31 14:10:06.051630", "memory_info": {"rss": 11939840, "vms": 4404228096, "pfaults": 531770, "pageins": 0}, "cpu_times": {"user": 0.583945792, "system": 0.66087648, "children_user": 0.0, "children_system": 0.0}, "elapsed_time": 12.42771601676941}
Then run TotalDepth.common.process
CLI entry point with two arguments, the log file and a directory to write the Gnuplot data to.
$ python src/TotalDepth/common/process.py tmp/process_C.log tmp/gnuplot_process
2019-10-31 14:11:29,737 - gnuplot.py - 86631 - (MainThread) - INFO - gnuplot stdout: None
2019-10-31 14:11:29,741 - gnuplot.py - 86631 - (MainThread) - INFO - Writing gnuplot data "process_C.log" in path tmp/gnuplot_process
2019-10-31 14:11:29,782 - gnuplot.py - 86631 - (MainThread) - INFO - gnuplot stdout: None
In the output directory there is the log data extracted as .dat
file, the Gnuplot specification as .plt
file, and the plot itself in SVG as process_C.log.svg
:
$ ls -l tmp/gnuplot_process/
total 360
-rw-r--r-- 1 xxxxxxxx staff 13679 31 Oct 14:11 process_C.log.dat
-rw-r--r-- 1 xxxxxxxx staff 1067 31 Oct 14:11 process_C.log.plt
-rw-r--r--@ 1 xxxxxxxx staff 30878 31 Oct 14:11 process_C.log.svg
-rw-r--r-- 1 xxxxxxxx staff 32100 31 Oct 14:11 test.svg
Here is process_C.log.svg
:
Adding Events as Graph Labels¶
You can also inject events into TotalDepth.common.process
as string messages and these will be reproduced on the plot as labels.
So adding one line of code:
import random
import time
from TotalDepth.common import process
with process.log_process(0.1):
for i in range(8):
size = random.randint(128, 128 + 256) * 1024 ** 2
process.add_message_to_queue(f'String of {size:,d} bytes')
s = ' ' * (size)
# Simulate 0.5 to 1.5 seconds of work.
time.sleep(0.5 + random.random())
del s
# Simulate 0.25 to 0.75 seconds of work.
time.sleep(0.25 + random.random() / 2)
Adds that label into the JSON on the next write:
{
"label": 'String of xxx bytes'
# ...
}
When plotted these labels appear on the plot:
A Real World Example¶
Here is an example of running TotalDepth.RP66V1.ScanHTML
on four files of sizes 75, 80, 8 and 500 MB.
TotalDepth.RP66V1.ScanHTML
essentially does two things:
- Creates an index of the RP66V1 file.
- Then iterates across that index writing HTML, this includes reading a (potentially) large number of frames depending on the file.
The start points of these operations are labeled on the graph.
The graphs clearly shows that for the last file reading the index is very quick but writing the HTML is comparatively slow. This is because that is an unusual file that deserves further investigation.