BlockingIOError on App Engine after some time

[drazzib]

After adding google-cloud-profiler==1.1.1 to my Python 3.7 App Engine project, I'm getting lots of

BlockingIOError: [Errno 11] Resource temporarily unavailable
Exception ignored when trying to write to the signal wakeup fd:

in my service stderr logs

I'm having the same issue either with App Engine Standard python3.7 or with App Engine Flex over a custom runtime (Docker image)

Is this a known issue, is there something I can do to mitigate this issue ?

[kalyanac]

@drazzib Thank you for reporting this. This is not a known issue. We will try to reproduce this issue.

[kalyanac]

Can you share your app.yaml, requirements.txt, Dockerfile? I tried with Quickstart apps on Profiling Python applications  |  Cloud Profiler  |  Google Cloud and did not see that messages.

[drazzib]

app.yaml:

runtime: custom
env: flex
manual_scaling:
  instances: 1
resources:
  cpu: 4
  memory_gb: 6
  disk_size_gb: 20
env_variables:
  FLASK_APP: main.py
  FLASK_ENV: production

requirements.txt:

wrapt==1.11.2
sklearn==0.0
Flask==1.1.1
gunicorn==20.0.4
future==0.18.2
h5py==2.10.0
google-cloud-storage==1.26.0
google-cloud-core==1.3.0
google-cloud-profiler==1.1.1
google-cloud-logging==1.15.0
pandas==1.0.2
datalab==1.1.5
Keras==2.3.1
Keras-Applications==1.0.8
Keras-Preprocessing==1.1.0
tensorflow-cpu==2.1.0
cachetools==4.1.0

Dockerfile:

FROM gcr.io/google-appengine/python

# Create a virtualenv for dependencies. This isolates these packages from
# system-level packages.
# Use -p python3 or -p python3.7 to select python version. Default is version 2.
RUN virtualenv -p python3 /env

# Setting these environment variables are the same as running
# source /env/bin/activate.
ENV VIRTUAL_ENV /env
ENV PATH /env/bin:$PATH

# Copy the application's requirements.txt and run pip to install all
# dependencies into the virtualenv.
ADD requirements.txt /app/requirements.txt
RUN pip install --upgrade pip
RUN pip install -r /app/requirements.txt

# Add the application source code.
ADD . /app

# Run a WSGI server to serve the application. gunicorn must be declared as
# a dependency in requirements.txt.
CMD gunicorn -c gunicorn.conf.py -b :$PORT main:app

[drazzib]

Hi @kalyanac & @jqll !

I've just seen that a new 1.1.2 release has been pushed to PyPI repository which contains 17d58aa commit.

Is this relevant for issue discussed above ?

[kalyanac]

Hi @drazzib, No the new release is not related to this issue. We are still having trouble reproducing this error.

[kalyanac]

Are you seeing any profiles collected despite these messages?

[drazzib]

Yes, I can confirm that - even with this error printed very often on stderr
there is still some collected profile visible on Google StackDriver Profiler UI

[kalyanac]

Thank you for the response. Few more questions:

• What profile types do you see in the Profiler UI?
• For each profile type, select a 10 minutes in Timespan, and check the profile count shown in the root node. The root node has the profile count displayed as "... averaged over n profiles". Please report what the n is.
• If the service is not running currently, please set the end time to a time when the service was running by clicking "Now" and setting the end time.

[kalyanac]

Gentle ping.

[drazzib]

Hi @kalyanac , sorry for the delay.

• In Profiler UI, I see both "CPU Time" et "Wall time" for my application
• For each profile type, under a 10 minutes in Timespan, I can see
  • for "CPU Time" 20.91 ms (100%), averaged over 11 profiles
  • for "Wall Time" 10 s (100%), averaged over 9 profiles

[kalyanac]

Hi @drazzib, it seems like the agent is uploading profiles at a rate we expect it to. So we don't anticipate any loss of profile data at the moment.

We'll try to reproduce this issue and root cause the source of the message.

[radyz]

I just started having this same issue today with my CloudRun service

Libs:
google-cloud-profiler = 1.1.2
gunicorn = 20.0.4
Django = 3

 Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/googlecloudprofiler/pythonprofiler.py", line 180, in _handler
    if not self._started or self._in_handler:
BlockingIOError: [Errno 11] Resource temporarily unavailable" 

[kalyanac]

@radyz thanks for reporting it.

[jqll]

Thanks for reporting the issue.

I think the problem is that the app enabled signal wakeup fd somewhere. When the profiler profiles, it triggers a SIGALRM/SIGPROF signal every 10ms. Since too many signals arrive too quickly, it may cause the fd’s buffer to be full, see https://docs.python.org/3/library/signal.html#signal.set_wakeup_fd:

There are two common ways to use this function. In both approaches, you use the fd to wake up when a signal arrives, but then they differ in how they determine which signal or signals have arrived.

In the first approach, we read the data out of the fd’s buffer, and the byte values give you the signal numbers. This is simple, but in rare cases it can run into a problem: generally the fd will have a limited amount of buffer space, and if too many signals arrive too quickly, then the buffer may become full, and some signals may be lost. If you use this approach, then you should set warn_on_full_buffer=True, which will at least cause a warning to be printed to stderr when signals are lost.

In the second approach, we use the wakeup fd only for wakeups, and ignore the actual byte values. In this case, all we care about is whether the fd’s buffer is empty or non-empty; a full buffer doesn’t indicate a problem at all. If you use this approach, then you should set warn_on_full_buffer=False, so that your users are not confused by spurious warning messages.

This will not affect the profiler. But if the app definitely needs to access the signal numbers as described in the first approach above, you probably should not use the profiler.