Skip to content

Profile mem #678

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 8 commits into from
Nov 23, 2022
Merged

Profile mem #678

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
3449cf7
ocrd process: simple memory usage measurement
kba Mar 4, 2021
0cfa612
fix profiler logging test
kba Mar 4, 2021
7e78a5d
ocrd process: memory_usage w/ multiprocess and include_children
kba Mar 4, 2021
f005897
Merge branch 'master' into profile-mem
bertsky Oct 12, 2022
342316e
Update ocrd/ocrd/processor/helpers.py
kba Nov 23, 2022
a103ac9
mem_usage: run process only once
kba Nov 23, 2022
4fdfbf3
Implement OCRD_PROFILE{_FILE} environemnt variable to configure CPU/m…
kba Nov 23, 2022
97a14b0
describe OCRD_PROFILE{,_FILE} in README
kba Nov 23, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 8 additions & 1 deletion ocrd/ocrd/processor/helpers.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,8 @@
import json
import inspect
from subprocess import run, PIPE
from memory_profiler import memory_usage
from sparklines import sparklines

from click import wrap_text
from ocrd_utils import getLogger
Expand Down Expand Up @@ -69,7 +71,12 @@ def run_processor(
log.debug("Processor instance %s (%s doing %s)", processor, name, otherrole)
t0_wall = perf_counter()
t0_cpu = process_time()
processor.process()
mem_usage = memory_usage(proc=processor.process, interval=.1, timeout=None, timestamps=True, multiprocess=True, include_children=True)
Copy link
Collaborator

@bertsky bertsky Sep 1, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
mem_usage = memory_usage(proc=processor.process, interval=.1, timeout=None, timestamps=True, multiprocess=True, include_children=True)
mem_usage = memory_usage(proc=processor.process,
interval=.1, timeout=None, timestamps=True,
# include sub-processes
multiprocess=True, include_children=True,
# get proportional set size instead of RSS
backend='psutil_pss')

Copy link
Collaborator

@bertsky bertsky Oct 12, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If it is really that simple – let's make this configurable (PSS vs RSS measuring). Did you try this?

Copy link
Member Author

@kba kba Oct 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, however we first need a mechanism to toggle this behavior. Simple idea would be to add CLI flags --mem-profile-rss and --mem-profile-pss.

@bertsky prefers a way to have this configurable via the logging configuration - @M3ssman do you have a good idea how that might work? That way, we could keep the CLI arguments small and the --help output less confusing.

Copy link
Collaborator

@bertsky bertsky Oct 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps for the moment it could be as simple as

mem_prof = os.getenv('OCRD_PROFILE', '')
if mem_prof:
    ...
        backend='psutil_pss' if mem_prof == 'PSS' else 'psutil')

Copy link
Member Author

@kba kba Oct 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like environment variables in general, but when the choice is between environment variables and CLI flags, I prefer the latter, because at least it's consistent. Because otherwise you could get OCRD_PROFILE=PSS ocrd-dummy --profile-file my.prof ....

Copy link
Collaborator

@bertsky bertsky Oct 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kba I agree, however I did not argue env var plus cli arg, but only the former. Perhaps we could also move --profile and --profile-file into env var control entirely.

Or we go the other direction and put everything into a single CLI arg, just with multi-faceted value: --profile mem=rss,cpu,file=foo.log for example.

For the broader discussion of how to configure processors without adding to many options / parameters and what for, see this old thread

Copy link
Member Author

@kba kba Nov 23, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, now that the wonky multiple-process-call behavior is fixed, I'll implement this via environment variable OCRD_PROFILE and OCRD_PROFILE_FILE

  • OCRD_PROFILE not set or empty: no profiling
  • OCRD_PROFILE_FILE set to a value (== current --profile-file flag):
    • if OCRD_PROFILE is defined but empty: no profiling
    • if OCRD_PROFILE is not defined: set OCRD_PROFILE to CPU
      * if OCRD_PROFILE is defined but does not contain CPU: raise error too strict, PROFILE_FILE should imply PROFILE^=CPU
  • OCRD_PROFILE contains CPU, do CPU profiling (== current --profile flag)
  • OCRD_PROFILE contains RSS do RSS memory profiling
  • OCRD_PROFILE contains PSS: do proportionate mem profiling
  • If OCRD_PROFILE contains both PSS and RSS: raise error too strict, PSS takes precedence

Did I catch everything?

Copy link
Member Author

@kba kba Nov 23, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Implemented in 4fdfbf3

Copy link
Contributor

@MehmedGIT MehmedGIT Nov 23, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Environment variables look good to me.

In the readme, I would also suggest to reference an external link where the difference between RSS and PSS is explained or at least briefly described. May not be the best suggestion, but consider this.

Copy link
Collaborator

@bertsky bertsky Nov 23, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, sounds reasonable and complete AFAICS – thx!

mem_usage_values = [mem for mem, _ in mem_usage]
mem_output = 'memory consumption: '
mem_output += ''.join(sparklines(mem_usage_values))
mem_output += ' max: %.2f MiB min: %.2f MiB' % (max(mem_usage_values), min(mem_usage_values))
logProfile.info(mem_output)
t1_wall = perf_counter() - t0_wall
t1_cpu = process_time() - t0_cpu
logProfile.info("Executing processor '%s' took %fs (wall) %fs (CPU)( [--input-file-grp='%s' --output-file-grp='%s' --parameter='%s']" % (
Expand Down
2 changes: 2 additions & 0 deletions ocrd/requirements.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,3 +8,5 @@ Flask
jsonschema
pyyaml
Deprecated == 1.2.0
memory-profiler >= 0.58.0
sparklines >= 0.4.2
4 changes: 3 additions & 1 deletion tests/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -167,7 +167,9 @@ def testProcessorProfiling(self):
# with open('/tmp/debug.log', 'w') as f:
# f.write(log_contents)
# Check whether profile information has been logged. Dummy should finish in under 0.1s
self.assertTrue(match(r'.*Executing processor \'ocrd-test\' took 0.\d+s.*', log_contents))
# print(log_contents)
assert "Executing processor 'ocrd-test' took 0" in log_contents
# self.assertTrue(match(r'.*Executing processor \'ocrd-test\' took 0.\d+s.*', log_contents))

def test_tmpConfigfile(self):
self.assertNotEqual(logging.getLogger('').getEffectiveLevel(), logging.NOTSET)
Expand Down