Logging #368

NikoOinonen · 2025-11-03T13:14:17Z

Fixes #214

This changes all print statements in the Python code to use the built-in logging module instead. The logging events are divided into different levels, see https://docs.python.org/3/library/logging.html#levels, so that the user can control the amount and format of the output from ppafm. I set the default level at INFO and only left high level info at that level so that more detailed output is at DEBUG level which is not printed by default. You can see in the code if you agree with my judgement and we can adjust.

There is still some output coming from the C++ code which just goes to stdout, but that's for another time. I also didn't touch the dev module and some of the CLI scripts that are not part of the ppafm pip package.

Controlling the logging output

In the code the logging level is controlled by using differently named methods for each level in the logger objects that I defined for each module. For example logger.info("This is important information"), or logger.debug("This is debug information").

The output at runtime can be controlled two different ways:

Programmatically in scripts using the configure_logging function in the new logging_utils module
Using the following new environment variables:

PPAFM_LOG_LEVEL sets the log level. All message more severe than the set level are printed. For example PPAFM_LOG_LEVEL=DEBUG to print everything.
PPAFM_LOG_PATH sets the file where the log is printed. If not specified (default), then the log goes to stdout. For example PPAFM_LOG_PATH=my_ppafm_run.log.
PPAFM_LOG_FORMAT sets the format of printed log messages. There are several keywords you can use, see: https://docs.python.org/3/library/logging.html#logrecord-attributes. By default only the plain message is printed for info or "WARNING/ERROR: message" for more severe, or if the log level is at DEBUG then more detailed message with timestamp and the originating module name is printed. For example PPAFM_LOG_FORMAT="%(asctime)s - %(message)s".
PPAFM_LOG_PERFORMANCE controls whether timings for benchmarking are logged. Mostly relevant for the OpenCL code for now. Setting any value to the variable enables the log, for example PPAFM_LOG_PERFORMANCE=1.

We could add arguments to the CLI scripts as well, but I left it out for now since we are intending to overhaul that system anyways.

ondrejkrejci

Huge work @NikoOinonen ! I have many comments there. It seems to me, that we are slightly inconsistent with what is debug, warning and info. Still after some comments, I am more for approval, as we can change those later.

examples/Generator/inverse_trainer_xyz.py

ondrejkrejci · 2025-11-03T14:29:19Z

ppafm/GUIWidgets.py

-        if self.verbose > 1:
-            print("updateView time [s]", time.perf_counter() - t0)
+        logger.debug(f"FFViewer.updateView {ic} {iz} {data.shape}")
+        perf_logger.info(f"updateView time [s] {time.perf_counter() - t0}")


What is the perf_logger here? is it about performance - and that is instead of verbose > 1 ?

I previously had the performance benchmark prints at higher verbose level, but now it's in a separate system that can be enabled as needed. Basically performance logger prints lines with info on the amount of time taken for various tasks, for example:

[2025-11-04 09:40:57,436 - ppafm.perf.AFMulator] evalAFM [s]: 0.05937764700001935

ondrejkrejci · 2025-11-03T14:30:08Z

ppafm/GUIWidgets.py

        xyzs = self.parent.xyzs - lvec[0]
        atomstring = io.primcoords2Xsf(self.parent.Zs, xyzs.T, lvec)
-        io.saveXSF(fileName, data, lvec, head=atomstring, verbose=0)
+        io.saveXSF(fileName, data, lvec, head=atomstring)


Is it the information about verbosity send through somehow?

The verbosity level is now handled globally by setting the logger logging level, so there is no need to pass it manually everywhere.

ondrejkrejci · 2025-11-03T14:31:40Z

ppafm/GridUtils.py

 from . import cpp_utils
+from .logging_utils import get_logger
+
+logger = get_logger("GridUtils")


Why the file/routine type has to be passed to the logger function?

It's just a label that allows differentiating between messages coming from different modules if needed. The name is used in the log format with %(name)s. For example setting PPAFM_LOG_FORMAT="%(name) - %(message)s" will print lines like:

ppafm.HighLevel - Saving Lennard-Jones force field to xsf

The ppafm. will be prepended to the name because the logger is hierarchically derived from a logger with the name ppafm.

ondrejkrejci · 2025-11-03T14:33:01Z

ppafm/HighLevel.py

-    if verbose > 0:
-        print(" zTips : ", zTips)
+    logger.info(">>BEGIN: relaxedScan3D_omp()")
+    logger.debug(f" zTips : {zTips}")


I understand why, but it is just funny, that one, of the verbose > 0 is info and other is debug.

ondrejkrejci · 2025-11-03T16:50:31Z

ppafm/logging_utils.py

+
+    if level is None:
+        try:
+            level = os.environ["PPAFM_LOG_LEVEL"]


Do we set this how? During a pip installation?

They are normal environment variables that you can set as you run your calculation, either for the whole session with export PPAFM_LOG_LEVEL=DEBUG or just for the one run by prepending, e.g.:

PPAFM_LOG_LEVEL=DEBUG ./run.sh

We should add this to our WIKI.

ondrejkrejci · 2025-11-03T16:52:06Z

ppafm/ml/CorrectionLoop.py

    looper.startLoop(molecule, atomMap, bondMap, lvecMap, AFMRef)
    ErrConv = 0.1
-    print("# ------ To Loop    ")
+    logger.debug("# ------ To Loop    ")


Sounds like info to me.

Changed it.

ondrejkrejci · 2025-11-03T16:57:27Z

ppafm/ocl/field.py

        if bCopy:
            FE = self.downloadFF(FE)
-        if bFinish:
+        if bFinish or perf_log_enabled():


I am wondering, if bFinish is still necessary in the function.

It's maybe not that useful, but it's doing a different thing. You could possibly want to wait for the computation to finish even when not logging the performance.

ondrejkrejci · 2025-11-03T17:00:38Z

ppafm/ocl/oclUtils.py

-            print("  LOCAL_MEM_SIZE           = ", device.get_info( cl.device_info.LOCAL_MEM_SIZE           ) / 4, " float32")
-            print("  MAX_CONSTANT_BUFFER_SIZE = ", device.get_info( cl.device_info.MAX_CONSTANT_BUFFER_SIZE ) / 4, " float32")
-            print("  MAX_WORK_GROUP_SIZE      = ", device.get_info( cl.device_info.MAX_WORK_GROUP_SIZE      ))
+            logger.info("---------------------------------------------------------------")


Ha, Ha, I would have many things from here, such as speed and mem sizes as debug.

We don't actually use this function anywhere in the code at the moment. It's more of a developer testing thing for figuring out what capability the device has. I think all of the things here should be at the same log level, whether it's info or debug.

ondrejkrejci · 2025-11-03T17:03:05Z

ppafm/logging_utils.py

maybe somebody more skilled with this like @yakutovicha should have look at this. I do not see there any damage, but to be honest, I am not fully understanding what is going on there.

ondrejkrejci

Looks good to me, Just we should put to the WIKI how to set the PPAFM_LOG_LEVEL=DEBUG and what are the possible levels.

NikoOinonen added 7 commits October 28, 2025 13:58

Add new module logging_utils and update main modules to use it.

de2e62b

Update OCL modules to use logging_utils.

d0ee140

Update PPPlot slice plotting to use logging_utils.

a62861e

Update ml and defaults to use logging_utils.

019cba7

Update CLI scripts to use logging_utils.

5a4d6d0

Fix logging problems that were coming up in tests.

497e01c

Update default logging format.

977d89d

NikoOinonen requested review from ProkopHapala, mondracek, ondrejkrejci and yakutovicha November 3, 2025 13:14

ondrejkrejci reviewed Nov 3, 2025

View reviewed changes

NikoOinonen added 2 commits November 4, 2025 09:56

Fix logging format handling and change some debug to info.

9668798

Modify some logging levels.

9390e59

NikoOinonen force-pushed the logging branch from 989034d to 9390e59 Compare November 4, 2025 11:50

Make logging initialization more explicit in __init__.py.

b7dc650

ondrejkrejci approved these changes Nov 5, 2025

View reviewed changes

Logging #368

Are you sure you want to change the base?

Logging #368

Uh oh!

Conversation

NikoOinonen commented Nov 3, 2025

Controlling the logging output

Uh oh!

ondrejkrejci left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ondrejkrejci left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants