Bug in using Khiops with env vars to enable memory stats log analysis

[marcboulle]

Description

Khiops peut-être paramétré via des variables d'environnement pour analyser finement le profil d'utilisation mémoire et cpu au cours de l'exécution des tâches de l'outil.
Ce mode d'utilisation est d'usage interne pour l'équipe de développement, et il est très précieux pour auditer les éventuels problèmes de performance.

On peut le lancer avec la version core de Khiops, mais son lancement via Khiops python aboutit actuellement à un bug.

Lancement depuis core

Exemple de scenario de base, d'apprentissage sur la base Adult, sur un PC windows:

ClassManagement.OpenFile       // Open...
ClassFileName C:\Users\Public\khiops_data\samples\Adult\Adult.kdic     // Dictionary file
OK                             // Open

TrainDatabase.DatabaseSpec.Data.DatabaseFiles.List.Key       // List item selection
TrainDatabase.DatabaseSpec.Data.DatabaseFiles.DataTableName C:\Users\Public\khiops_data\samples\Adult\Adult.txt          // Data table file
AnalysisSpec.TargetAttributeName class   // Target variable
AnalysisSpec.PredictorsSpec.ConstructionSpec.MaxTreeNumber 0 // Max number of trees
AnalysisResults.ReportFileName C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\AnalysisResults.khj     // Analysis report
ComputeStats                   // Train model
Exit                           // Close
OK                             // Yes

Fichier de commande Windows de lancement de Khiops, en ayant paramétré les variables d'environnement:

REM Set parameters to collect mem stats logs
REM - KhiopsMemStatsLogFileName: None, memory stats log file name
REM - KhiopsMemStatsLogFrequency: None, frequency of allocator stats collection (0, 100000, 1000000,...)
REM - KhiopsMemStatsLogToCollect: None, stats to collect (8193: only time and labels, 16383: all,...)
REM - KhiopsIOTraceMode: None, to collect IO trace (false, true) (beware: can be verbose)
set KhiopsMemStatsLogFileName=C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\MemStats\KhiopsMemoryStats.log
set KhiopsMemStatsLogFrequency=100000
set KhiopsMemStatsLogToCollect=16383

call "%KHIOPS_HOME%\bin\khiops" -i scenario_train_adult._kh -e C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\log.txt -b

On obtient alors les logs souhaités dans le répertoire
C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\MemStats.

A noter: avec ce mode d'utilisation, Khiops core écrit des informations dans la console, rappelant le contexte:

MemoryStatsManager activated
	KhiopsMemStatsLogFileName=C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\MemStats\KhiopsMemoryStats.log
	KhiopsMemStatsLogFrequency=100000
	KhiopsMemStatsLogToCollect=16383
MemoryStatsManager activated
	KhiopsMemStatsLogFileName=C:\Users\Public\khiops_data\samples\Adult\TrainWithLogs\MemStats\KhiopsMemoryStats.log
	KhiopsMemStatsLogFrequency=100000
	KhiopsMemStatsLogToCollect=16383
...

Lancement depuis khiops python

Script python équivalent:

# Imports
import os
from khiops import core as kh

# Set the file paths
adult_path = os.path.join(kh.get_samples_dir(), "Adult")
dictionary_file_path = os.path.join(adult_path, "Adult.kdic")
data_table_path = os.path.join(adult_path, "Adult.txt")
analysis_report_file_path = os.path.join(adult_path, "TrainWithLogs", "AnalysisResults.khj")
log_file_path = os.path.join(adult_path, "TrainWithLogs", "log.txt")

# Set parameters to collect mem stats logs
# - KhiopsMemStatsLogFileName: None, memory stats log file name
# - KhiopsMemStatsLogFrequency: None, frequency of allocator stats collection (0, 100000, 1000000,...)
# - KhiopsMemStatsLogToCollect: None, stats to collect (8193: only time and labels, 16383: all,...)
# - KhiopsIOTraceMode: None, to collect IO trace (false, true) (beware: can be verbose)
os.environ['KhiopsMemStatsLogFileName'] = os.path.join(adult_path, "TrainWithLogs", "MemStats", "KhiopsMemoryStats.log")
os.environ['KhiopsMemStatsLogFrequency'] = '100000'
os.environ['KhiopsMemStatsLogToCollect'] = '16383'

# Train the predictor
try:
    kh.train_predictor(
        dictionary_file_path,
        "Adult",
        data_table_path,
        "class",
        analysis_report_file_path,
        max_trees=0,
        log_file_path=log_file_path
    )
except Exception as e:
    print(f"An error occurred: {e}")

Cela marche en commentant les lignes de paramétrage des variables d'environnement.
Sinon, cela plante, avec le message d'erreur suivant:

An error occurred: cannot access local variable 'khiops_version_str' where it is not associated with a value
Process finished with exit code 0

Questions/Ideas

Hypothèse sur le dysfonctionnement:

• un bug interne n'est pas géré en cas de fonctionnement non nominal
• ce fonctionnement non nominal est probablement déclenché par les informations émises par Khiops core dans la console

[folmos-at-orange]

Cannot reproduce in macOS, maybe it is Windows related ?

[tramora]

With these 3 env variables defined, "Khiops core" outputs indeed such lines for every run

MemoryStatsManager activated
	KhiopsMemStatsLogFileName=log.txt
	KhiopsMemStatsLogFrequency=100000
	KhiopsMemStatsLogToCollect=16383
Khiops 10.3.1

Unfortunately it always uses a Unix separator as a line separator for this output.

When parsing the lines to get information like the khiops version, khiops-python uses a OS specific line separator.
That's why the error occurs only on Windows and not on Linux or MacOS systems (as @folmos-at-orange confirmed above)

The easy fix was to get the lines without assuming a specific OS.

[popescu-v]

Cannot reproduce in macOS, maybe it is Windows related ?

It is related to

khiops-python/khiops/core/internals/runner.py

Line 956 in e4ebcdc

for line in stdout.split(os.linesep):

The most straighforward fix consists IMHO in what @tramora proposed in PR #439.
However, this seems to circumvent a behavior that could be updated on the Khiops Core side: the binaries could also be made to use OS-specific line separators for these logs, as it is done for standard logs.

[popescu-v]

After discussion, the fix is to be done on the Python side, by:

• first splitting on \n systematically;
• then, stripping trailing \r from the resulting lines.

[popescu-v]

Closed by PR #439.