Timestamps in logs - GSOC 2025

[t0hsumi]

@PhilippWendler I'm very interested in working on solving the timestamp issue as my GSoC 2025 project. I'll apply, but I have several questions:

• Would using a shell pipe be insufficient to solve Prevent truncation of output file by tool #535? At first glance, I believe a shell pipe wouldn't affect the 'benchmarked' environment. However, I'm not sure if this is the right approach.
• Are there any specific expectations regarding the implementation of this feature? You listed three possible solutions in Prevent creation of large log files #536. Does the choice depend on the project size (small or medium)? Have you considered any other possible solutions?

Thanks.

[PhilippWendler]

Hello and welcome to our project! Thanks for your interest!

Using a pipe in principle solves #535. But we would not want to involve a shell here, because the more processes we start the more complex everything becomes. It should be handled completely inside BenchExec.

For #536, the question is what works best in practice. For example, if the memfd solution really breaks > /dev/stdout, it would probably be better to use something else. If we decide to use a pipe anyway for #535, it would be natural to use it for implementing #536 as well.

I am always open for suggestions of other solutions, but all those that I became aware of are listed in the issue.

[t0hsumi]

Thanks for your quick response and detailed explanation!

I understand your motivation to keep the complexity under control.
For now, I think implementing a pipe using threading or asyncio would be a good approach.
I also considered controlling I/O bandwidth using cgroups, but this might unintentionally restrict the necessary I/O for the programs (if any).

In any case, I'll take a closer look at the code and try to submit some PRs if possible.

Thanks!

[PhilippWendler]

Sounds good!

[PhilippWendler]

We are really happy to be able to announce that @t0hsumi got accepted into GSoC with this project proposal! Congratulations!

[t0hsumi]

Implementation plan detail

Hi @PhilippWendler ,

my current implementation plan uses non-blocking I/O and selectors.
The sample code is below. (Note: We need to handle cases where the data does not contain a '\n', or where the data is not valid UTF-8.)

import subprocess
import selectors
import fcntl
import os


def add_nonblocking_flag(fd):
    fl = fcntl.fcntl(fd, fcntl.F_GETFL)
    fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)


sel = selectors.DefaultSelector()

proc = subprocess.Popen(
    ["bash", "-c", 'echo "echo_stdout1" ; echo "echo_stderr1" 1>/dev/stderr ; echo "echo_stdout2"'],
    stdout=subprocess.PIPE,
    stderr=subprocess.PIPE
)

add_nonblocking_flag(proc.stdout.fileno())
add_nonblocking_flag(proc.stderr.fileno())

sel.register(proc.stdout, selectors.EVENT_READ, data="STDOUT")
sel.register(proc.stderr, selectors.EVENT_READ, data="STDERR")

while True:
    for key, _ in sel.select():  # Blocks until ready
        data = os.read(key.fileobj.fileno(), 4096)
        if not data:
            sel.unregister(key.fileobj)
        else:
            print(f"[{key.data}] {data.decode().strip()}")
    if proc.poll() is not None and not sel.get_map():
        break

proc.stdout.close()
proc.stderr.close()
sel.close()

I believe we don’t need to manage timeouts in this implementation.
What do you think about this approach?

[PhilippWendler]

I think in general this should work as we need it, yes. I don't have much experience with non-blocking I/O in Python, though, so I cannot really comment on whether this is the best way.

Do we even need to mark the file descriptors as non-blocking if we use them with select()?

I am not sure whether it is ok for the subprocess module if we ask it to create pipes for us and then do stuff like this with its file descriptors, or whether we should instead use own pipes. Is there something in the docs about what we are allowed to do with the file descriptors?

For the long term, it would be really nice if we could integrate this loop with other stuff that we need to do while the process is running, e.g., checking for time limits etc. Ideal would be if we need no other thread except the main thread. This is not something that we want to tackle right now, let's focus on the current issue. But if we find some way to handle the I/O where we already know that it will facilitate doing more in the future, this would be nice.

[t0hsumi]

My sample implementation is based on a combination of the following two resources:

• https://stackoverflow.com/questions/7729336/how-can-i-print-and-display-subprocess-stdout-and-stderr-output-without-distorti
• https://dnmtechs.com/implementing-non-blocking-read-on-subprocess-pipe-in-python-3/

The first source explains how to update subprocess.PIPE using fcntl.

I couldn’t find any official documentation or open-source projects using pipes in this way, but I thought it was important to set both the command output and the thread reading from that output to non-blocking mode. To achieve this, I added an add_nonblocking_flag() function.

However, the current implementation does not update subprocess.PIPE directly. This may affect benchmarking results or the environment in which benchmarks are run. Since adding add_nonblocking_flag() is straightforward, I think it’s worth checking whether there's a measurable difference with and without this function.

NOTE: I also found a implementation using Queue: https://stackoverflow.com/questions/375427/a-non-blocking-read-on-a-subprocess-pipe-in-python

[PhilippWendler]

Yes, I would simply try it out whether add_nonblocking_flag() is necessary. The Queue solution from SO does blocking I/O in a separate thread. This works, but then we need two more threads per run, and it has higher latency. A solution with a single loop like in the select() prototype would be nicer.

[t0hsumi]

OK, I'm going to implement pipes using select().

[t0hsumi]

Testing Detail

Could you clarify how to evaluate the impact of the new feature on BenchExec?
Regarding the benchmarked environment, are the outputs generated by BenchExec sufficient for evaluation?
Also, are there any test modules commonly used to assess the feature's effect on the benchmarking setup?
If not, I think it would be a good idea to write some scripts to help evaluate that.

[PhilippWendler]

The output of BenchExec would certainly be an important part. In addition, I think that we should also measure CPU time, wall time, and memory usage of BenchExec itself. This should not be difficult, I think one could either use a script around BenchExec (but then one has do implement some cgroup handling), or simply add those measurements to localexecution.py. There we already have wall-time measurement actually, and just need to add CPU time and memory.

With test modules, you mean a benchmark suite? I would suggest to use a subset of SV-COMP (https://sv-comp.sosy-lab.org/reproduce.php). This has both a diverse range of tools to benchmark plus configurations and inputs.

[t0hsumi]

With test modules, you mean a benchmark suite? I would suggest to use a subset of SV-COMP (https://sv-comp.sosy-lab.org/reproduce.php). This has both a diverse range of tools to benchmark plus configurations and inputs.

By test modules, I actually meant something like a bash script that monitors BenchExec itself. You already addressed that point above—thank you so much!
To summarize, I’m going to compare the output of BenchExec with and without the new feature, and also monitor BenchExec’s own CPU time, wall time, and memory usage, using a subset of SV-COMP as the benchmark suite :)

[t0hsumi]

Timeline update

Here is the updated timeline. I believe I can complete this project in 10 weeks.
Note: I have the university final exams until June 13th, so progress may be slightly delayed during the first two weeks.

• Week 1 (June 2 - June 8)
  Gain a detailed understanding of the current implementation
  Implement the pipe in the BaseExecutor class (1/2)

• Week 2 (June 9 - June 15)
  Implement the pipe in the BaseExecutor class (2/2)

• Week 3 (June 16 - June 22)
  Check whether any parts need to be modified in the ContainerExecutor and RunExecutor classes due to the implementation from the previous step
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments (1/2)

• Week 4 (June 23 - June 29)
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments (2/2)

• Week 5 (June 30 - July 6)
  Implement the buffer in the BaseExecutor class

• Week 6 (July 7 - July 13)
  Prepare for midterm evaluation
  Check whether any parts need to be modified in the ContainerExecutor and RunExecutor classes due to the implementation of the buffer

• Week 7 (July 14 - July 20)
  Modify the --maxOutputSize option in the ContainerExecutor and RunExecutor classes (1/2)

• Week 8 (July 21 - July 27)
  Modify the --maxOutputSize option in the ContainerExecutor and RunExecutor classes (2/2)
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments

• Week 9 (July 28 - August 3)
  Implement --timestamp option
  Debug and add tests

• Week 10 (August 4 - August 10)
  Create a final report for final review
  Debug and add tests

[PhilippWendler]

Sounds fine for me. Currently we cannot edit the project length on the GSoC page, Google asked us to wait for a few days. But there is no hurry to do so anyway.

[PhilippWendler]

I updated the project to 10 weeks now on the GSoC page. Note that the midterm evaluation is in the week July 07 - July 11, so the "Prepare for midterm evaluation" task in your timeline would need to be in the week before you planned it.

[t0hsumi]

Thanks for the update! Here's the finalized version of the schedule (I'm currently busy preparing for final exams, so I'll start working from next week):

• Week 1 (June 2 - June 8)
  Gain a detailed understanding of the current implementation
  Implement the pipe in the BaseExecutor class (1/2)

• Week 2 (June 9 - June 15)
  Implement the pipe in the BaseExecutor class (2/2)

• Week 3 (June 16 - June 22)
  Check whether any parts need to be modified in the ContainerExecutor and RunExecutor classes due to the implementation from the previous step
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments (1/2)

• Week 4 (June 23 - June 29)
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments (2/2)

• Week 5 (June 30 - July 6)
  Prepare for midterm evaluation
  Implement the buffer in the BaseExecutor class

• Week 6 (July 7 - July 13)
  Check whether any parts need to be modified in the ContainerExecutor and RunExecutor classes due to the implementation of the buffer

• Week 7 (July 14 - July 20)
  Modify the --maxOutputSize option in the ContainerExecutor and RunExecutor classes (1/2)

• Week 8 (July 21 - July 27)
  Modify the --maxOutputSize option in the ContainerExecutor and RunExecutor classes (2/2)
  Confirm that the changes in the previous steps do not cause any unwanted negative side effects to the benchmarking environments

• Week 9 (July 28 - August 3)
  Implement --timestamp option
  Debug and add tests

• Week 10 (August 4 - August 10)
  Create a final report for final review
  Debug and add tests

[t0hsumi]

Progress Made up (Jun 21th)

All the code is available on the branch add-output-selector.

Current Progress

I implemented the pipe using selectors module which works properly when the examined tool sends EOF.

In #1151 (reply in thread), my mentor, Dr. Philipp, asked me whether it is necessary to mark the file descriptors as non-blocking if we use them with select(). According to the documentation, "The operation of select() and pselect() is not affected by the O_NONBLOCK flag. (man 2 select)". Therefore I stopped adding the O_NONBLOCK flag.

Comparison to Plan

According to my original plan, I aimed to finish the pipe implementation by the end of week 2, so currently the progress is behind schedule. I plan to allocate additional time to complete the implementation.

Challenges

There are the case where the current implementation doesn't work correctly, and I have a few questions.

1. runexec doesn't terminate when the tool doesn't send EOF.

In some cases, the tool terminates without sending EOF (e.g., due to a signal or exceeding the walltime limit. See the pytest error case).
In my implementaion, the selector blocks until it detects some stdout or stderr.

benchexec/benchexec/baseexecutor.py

Lines 162 to 164 in 8a34a3e

	for key, _unused_event in selector.select():
	# Block until output is ready
	output = os.read(key.fileobj.fileno(), 4096)

To handle this, we need to process stdout and stderr while also checking for walltime limits and signals.
The only solution I’ve thought of so far is to use an additional thread, but I’m not sure if this is acceptable.

2. The size of the os.read()

I’ve currently set the read size to 4096 bytes. However, we may need to evaluate whether this is optimal in terms of performance.

3. Need for exception handling with selectors module

The methods of selectors module may raise the exceptions in some edge cases (e.g., ValueError on an invalid event mask or file descriptor during selectors.register()). In our current usage, these cases should not occur, so I’m unsure whether we need to add a try-catch block for safety.

Future Plan

We need to quickly address the issue of tools that terminate without sending EOF. After resolving this, I aim to complete the implementation by the end of week 4.

[PhilippWendler]

Hi, thanks for the writeup! I would think that technical questions about a particular implementation are best discussed close to that implementation, e.g. in the PR. Otherwise it will be hard to find these discussions again should a question about the choice come up in the future. So could you please post them in #1170?

[t0hsumi]

Progress Made up (July 4th)

All the code is available on the branch add-output-selector.
The main pull request is here: #1170.

Current Progress

I implemented the pipe using the selectors module, which works properly even when the examined tool doesn't send EOF, by combining it with the select module and pidfd. However, my mentor, Dr. Philipp, mentioned here that a solution without pidfd is preferable, as pidfd is relatively new and we want to avoid introducing a hard dependency.

Comparison to Plan

I originally aimed to complete the pipe implementation by the end of week 4, so I'm currently about two weeks behind schedule. This week, I returned to Japan and couldn’t dedicate much time due to the flight and related matters. However, I’ll have more time to focus over the next couple of weeks.

Challenges

I'm trying to implement the pipe without using pidfd, but selector.select() blocks even after the process terminates and sends a signal. This appears to be because some processes (or a process) keep the writing end of the subprocess.Popen() pipe open. I'm currently investigating which processes are doing this and trying to ensure their file descriptors are properly closed.

Future Plan

By the end of week 6, I aim to complete the pipe implementation and move on to performance analysis.