Skip to content

Logging #368

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

Open
NikoOinonen wants to merge 10 commits into
base: main
Choose a base branch
from
Open

Logging #368

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
de2e62b
Add new module logging_utils and update main modules to use it.
NikoOinonen Oct 28, 2025
d0ee140
Update OCL modules to use logging_utils.
NikoOinonen Oct 28, 2025
a62861e
Update PPPlot slice plotting to use logging_utils.
NikoOinonen Oct 28, 2025
019cba7
Update ml and defaults to use logging_utils.
NikoOinonen Oct 29, 2025
5a4d6d0
Update CLI scripts to use logging_utils.
NikoOinonen Oct 29, 2025
497e01c
Fix logging problems that were coming up in tests.
NikoOinonen Nov 3, 2025
977d89d
Update default logging format.
NikoOinonen Nov 3, 2025
9668798
Fix logging format handling and change some debug to info.
NikoOinonen Nov 4, 2025
9390e59
Modify some logging levels.
NikoOinonen Nov 4, 2025
b7dc650
Make logging initialization more explicit in __init__.py.
NikoOinonen Nov 4, 2025
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
4 changes: 3 additions & 1 deletion examples/Generator/inverse_trainer_xyz.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,9 @@
from ppafm.ocl.AFMulator import AFMulator
from ppafm.ocl.oclUtils import init_env

# from ppafm.logging_utils import configure_logging
# configure_logging(log_performance=True)


class ExampleTrainer(InverseAFMtrainer):
# We override this callback method in order to augment the samples with randomized tip distance and tilt
Expand Down Expand Up @@ -57,7 +60,6 @@ def on_sample_start(self):
QZs=[[0.1, 0, -0.1, 0]],
Qs=[[-10, 20, -10, 0]],
)
# trainer.bRuntime = True

# Augment molecule list with rotations and shuffle
trainer.augment_with_rotations_entropy(sphereTangentSpace(n=100), 30)
Expand Down
3 changes: 2 additions & 1 deletion examples/pyridineDensOverlap/run_gpu.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,11 +8,12 @@

import ppafm.ocl.field as FFcl
import ppafm.ocl.oclUtils as oclu
from ppafm.logging_utils import configure_logging
from ppafm.ocl.AFMulator import AFMulator

# Initialize an OpenCL environment. You can change i_platform to select the device to use
oclu.init_env(i_platform=0)
FFcl.bRuntime = True # Print timings
configure_logging(log_performance=True) # Print timings

# Load all input files
rho_tip, xyzs_tip, Zs_tip = FFcl.TipDensity.from_file("tip/density_CO.xsf")
Expand Down
59 changes: 25 additions & 34 deletions ppafm/GUIWidgets.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,10 @@
from PyQt5 import QtCore, QtWidgets

from . import io
from .logging_utils import get_logger, get_perf_logger

logger = get_logger("GUIWidgets")
perf_logger = get_perf_logger("GUIWidgets")

matplotlib.use("Qt5Agg")

Expand Down Expand Up @@ -118,19 +122,17 @@ class FigImshow(FigCanvas):

cbar = None

def __init__(self, parentWiget=None, parentApp=None, width=5, height=4, dpi=100, verbose=0):
def __init__(self, parentWiget=None, parentApp=None, width=5, height=4, dpi=100):
super(self.__class__, self).__init__(parentWiget=parentWiget, parentApp=parentApp, width=width, height=height, dpi=dpi)
self.fig.canvas.mpl_connect("button_press_event", self.onclick)
self.fig.canvas.mpl_connect("scroll_event", self.onscroll)
self.verbose = verbose
self.img = None
self.cbar = None

def plotSlice(self, F_stack, z_slice, title=None, margins=None, grid_selector=0, slice_length=None, points=[], cbar_range=None, extent=None):
F = F_stack[z_slice]

if self.verbose > 0:
print("plotSlice F.shape, F.min(), F.max(), margins", F.shape, F.min(), F.max(), margins)
logger.debug(f"plotSlice F.shape, F.min(), F.max(), margins {F.shape} {F.min()} {F.max()} {margins}")

if self.img is None or self.img.get_array().shape != F.shape:
self.axes.cla()
Expand All @@ -143,8 +145,7 @@ def plotSlice(self, F_stack, z_slice, title=None, margins=None, grid_selector=0,
for line in self.axes.lines:
line.remove()
self.axes.set_prop_cycle(None) # Reset color cycle
if self.verbose > 0:
print("plotSlice: reset points")
logger.debug("plotSlice: reset points")
else:
for p, (ix, iy) in zip(self.axes.lines, points):
x = np.atleast_1d(ix)
Expand All @@ -155,17 +156,15 @@ def plotSlice(self, F_stack, z_slice, title=None, margins=None, grid_selector=0,
if self.cbar == None:
self.cbar = self.fig.colorbar(self.img, ax=self.axes)
self.cbar.set_label("df (Hz)")
if self.verbose > 0:
print("plotSlice: added colorbar")
logger.debug("plotSlice: added colorbar")
self.img.set_clim(vmin=cbar_range[0], vmax=cbar_range[1])
self.cbar.mappable.set_clim(vmin=cbar_range[0], vmax=cbar_range[1])
else:
self.img.autoscale()
if self.cbar is not None:
self.cbar.remove()
self.cbar = None
if self.verbose > 0:
print("plotSlice: removed colorbar")
logger.debug("plotSlice: removed colorbar")

if extent is not None:
self.img.set_extent(extent)
Expand Down Expand Up @@ -197,9 +196,9 @@ def plotSlice2(self, F_stack, title=None, margins=None, grid_selector=0, slice_l
self.axes.cla()

F = F_stack
print("plotSlice F.shape, F.min(), F.max() ", F.shape, F.min(), F.max())
logger.debug(f"plotSlice F.shape, F.min(), F.max() {F.shape} {F.min()} {F.max()}")

print("self.margins", margins)
logger.debug(f"self.margins {margins}")
if alpha > 0 and big_len_image is not None:
F = F * (1 - alpha) + big_len_image * alpha
self.img = self.axes.imshow(F, origin="lower", cmap="viridis", interpolation="bicubic")
Expand Down Expand Up @@ -232,8 +231,7 @@ def onclick(self, event):
x = float(event.xdata)
y = float(event.ydata)
except TypeError:
if self.verbose > 0:
print("Invalid click event.")
logger.warning("Invalid click event.")
return
self.axes.plot([x], [y], "o", scalex=False, scaley=False)
self.draw()
Expand All @@ -247,15 +245,14 @@ def onscroll(self, event):
x = float(event.xdata)
y = float(event.ydata)
except TypeError:
if self.verbose > 0:
print("Invalid scroll event.")
logger.warning("Invalid scroll event.")
return
if event.button == "up":
direction = "in"
elif event.button == "down":
direction = "out"
else:
print(f"Invalid scroll direction {event.button}")
logger.warning(f"Invalid scroll direction {event.button}")
return
self.parent.zoomTowards(x, y, direction)

Expand Down Expand Up @@ -325,7 +322,7 @@ def save_dat(self):
fileName, _ = QtWidgets.QFileDialog.getSaveFileName(self, "Save df curve raw data", default_path, "Data files (*.dat)")
if fileName:
fileName = correct_ext(fileName, ".dat")
print("saving data to :", fileName)
logger.info(f"Saving data to: {fileName}")
data = []
data.append(np.array(self.figCan.axes.lines[0].get_xdata()))
for line in self.figCan.axes.lines:
Expand All @@ -338,7 +335,7 @@ def save_png(self):
fileName, _ = QtWidgets.QFileDialog.getSaveFileName(self, "Save df curve image", default_path, "Image files (*.png)")
if fileName:
fileName = correct_ext(fileName, ".png")
print("saving image to :", fileName)
logger.info(f"Saving image to: {fileName}")
self.figCan.fig.savefig(fileName, bbox_inches="tight")

def clearFig(self):
Expand All @@ -363,7 +360,7 @@ def setRange(self):
except:
pass
self.figCan.draw()
print("range: ", xmin, xmax, ymin, ymax)
logger.debug(f"range: {xmin} {xmax} {ymin} {ymax}")


# =======================
Expand Down Expand Up @@ -511,9 +508,8 @@ def updateParent(self):


class FFViewer(SlaveWindow):
def __init__(self, parent=None, title="View Forcefield", width=5, height=4, dpi=100, verbose=0):
def __init__(self, parent=None, title="View Forcefield", width=5, height=4, dpi=100):
super().__init__(parent=parent, title=title)
self.verbose = verbose

self.figCan = FigImshow(parent, width=width, height=height, dpi=dpi)
self.centralLayout.addWidget(self.figCan)
Expand Down Expand Up @@ -576,8 +572,7 @@ def updateFF(self):
if not self.isVisible():
set_widget_value(self.bxInd, iz)

if self.verbose > 0:
print("FFViewer.updateFF", self.FE.shape, iz, self.z_step, self.z_min)
logger.debug(f"FFViewer.updateFF {self.FE.shape} {iz} {self.z_step} {self.z_min}")

def updateView(self):
t0 = time.perf_counter()
Expand All @@ -588,10 +583,8 @@ def updateView(self):
data = self.FE[..., ic].transpose(2, 1, 0)
self.figCan.plotSlice(data, iz, title=f"z = {z:.2f}Å")

if self.verbose > 0:
print("FFViewer.updateView", ic, iz, data.shape)
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}")
Copy link
Collaborator

@ondrejkrejci ondrejkrejci Nov 3, 2025

Choose a reason for hiding this comment

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

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

Copy link
Collaborator Author

@NikoOinonen NikoOinonen Nov 4, 2025

Choose a reason for hiding this comment

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

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


def saveFF(self):
comp = self.slComponent.currentText()
Expand All @@ -602,12 +595,11 @@ def saveFF(self):
ext = os.path.splitext(fileName)[1]
if ext != ".xsf":
self.parent.status_message("Unsupported file type in force field save file path")
print(f"Unsupported file type in force field save file path `{fileName}`")
logger.error(f"Unsupported file type in force field save file path `{fileName}`")
return
self.parent.status_message("Saving data...")

if self.verbose > 0:
print(f"Saving force field data to {fileName}...")
logger.debug(f"Saving force field data to {fileName}...")
ic = self.slComponent.currentIndex()
data = self.FE.copy()
# Clamp large values for easier visualization
Expand All @@ -620,10 +612,9 @@ def saveFF(self):
lvec = self.parent.afmulator.lvec
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)
Copy link
Collaborator

@ondrejkrejci ondrejkrejci Nov 3, 2025

Choose a reason for hiding this comment

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

Is it the information about verbosity send through somehow?

Copy link
Collaborator Author

@NikoOinonen NikoOinonen Nov 4, 2025

Choose a reason for hiding this comment

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

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


if self.verbose > 0:
print("Done saving force field data.")
logger.info("Done saving force field data.")
self.parent.status_message("Ready")


Expand Down
11 changes: 7 additions & 4 deletions ppafm/GridUtils.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,9 @@
import numpy as np

from . import cpp_utils
from .logging_utils import get_logger

logger = get_logger("GridUtils")
Copy link
Collaborator

@ondrejkrejci ondrejkrejci Nov 3, 2025

Choose a reason for hiding this comment

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

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

Copy link
Collaborator Author

@NikoOinonen NikoOinonen Nov 4, 2025

Choose a reason for hiding this comment

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

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.


# ============================== interface to C++ core

Expand Down Expand Up @@ -97,7 +100,7 @@ def interpolate_cartesian(F, pos, cell=None, result=None):
if cell is not None:
setGridCell(cell)
nDim = np.array(pos.shape)
print(nDim)
logger.debug(nDim)
if result is None:
result = np.zeros((nDim[0], nDim[1], nDim[2]))
n = nDim[0] * nDim[1] * nDim[2]
Expand All @@ -120,9 +123,9 @@ def dens2Q_CHGCARxsf(data, lvec):
nDim = data.shape
Ntot = nDim[0] * nDim[1] * nDim[2]
Vtot = np.linalg.det(lvec[1:])
print("dens2Q Volume : ", Vtot)
print("dens2Q Ntot : ", Ntot)
print("dens2Q Vtot/Ntot : ", Vtot / Ntot)
logger.debug(f"dens2Q Volume : {Vtot}")
logger.debug(f"dens2Q Ntot : {Ntot}")
logger.debug(f"dens2Q Vtot/Ntot : {Vtot / Ntot}")
# Qsum = rho1.sum()
return Vtot / Ntot

Expand Down
Loading