[PR38292] corrupted profile info with -O[23] -fprofile-use

[Matthias Klose]

Binary package hint: gcc-4.4

seen with a profiled build (make profile-opt
PROFILE_TASK='$(srcdir)/Lib/test/regrtest.py') building python-3.0rc3 on
i486-linux-gnu. Using pybench as the PROFILE_TASK doesn't show this bug).

gcc -pthread -c -fno-strict-aliasing -DNDEBUG -g -O2 -Wall -Wstrict-prototypes
-fprofile-use -I. -IInclude -I../Include -DPy_BUILD_CORE -o Modules/config.o
Modules/config.c
../Python/thread.c: In function 'PyThread_acquire_lock':
../Python/thread.c:419: error: corrupted profile info: number of executions for
edge 16-3 thought to be -1
../Python/thread.c:419: error: corrupted profile info: number of executions for
edge 16-17 thought to be 5657524
make[3]: *** [Python/thread.o] Error 1

[Jakub-gcc (jakub-gcc)]

Subject: Bug 38292

Author: jakub
Date: Wed Feb 4 19:50:58 2009
New Revision: 143937

URL: http://gcc.gnu.org/viewcvs?root=gcc&view=rev&rev=143937
Log:
 PR tree-optimization/38977
 PR gcov-profile/38292
 * calls.c (special_function_p): Disregard __builtin_
 prefix.

Modified:
    trunk/gcc/ChangeLog
    trunk/gcc/calls.c

[Matthias Klose (doko)]

still seen with a backport of the patch to the 4.3 branch and with trunk 20090211 on amd64. works on i486.

gcc -pthread -c -fno-strict-aliasing -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -fprofile-use -I. -IInclude -I../Include -DPy_BUILD_CORE -o Modules/config.o Modules/config.c
../Python/thread.c: In function 'PyThread_acquire_lock':
../Python/thread.c:423: error: corrupted profile info: profile data is not flow-consistent
../Python/thread.c:423: error: corrupted profile info: number of executions for edge 16-3 thought to be -7
../Python/thread.c:423: error: corrupted profile info: number of executions for edge 16-17 thought to be 4920917

[Rguenth (rguenth)]

Can you check if moving the PR38977 fix to special_function_p (handling
plain fork there) fixes it? What is the contents of thread.c?

[Matthias Klose (doko)]

Created attachment 17286
thread.c source file

[Matthias Klose (doko)]

Created attachment 17287
thread_pthread.h header

[Matthias Klose (doko)]

a build with the suggested change doesn't show any change.

--- gcc/calls.c~ 2009-02-05 09:30:24.000000000 +0100
+++ gcc/calls.c 2009-02-12 15:17:08.000000000 +0100
@@ -530,6 +530,8 @@
        }
       else if ((tname[0] == 'q' && tname[1] == 's'
                && ! strcmp (tname, "qsetjmp"))
+ || (tname[0] == 'f' && tname[1] == 'o'
+ && ! strcmp (tname, "fork"))
               || (tname[0] == 'v' && tname[1] == 'f'
                   && ! strcmp (tname, "vfork"))
               || (tname[0] == 'g' && tname[1] == 'e'

[Matthias Klose (doko)]

seen as well on sparc-linux, x86_64-linux and i486-linux (when built with -mcpu=i686 -mtune=i586), although triggered in different files.

[Matthias Klose (doko)]

same behaviour with the 4.4.1 release

[Rguenth (rguenth)]

GCC 4.3.4 is being released, adjusting target milestone.

[Rguenth (rguenth)]

GCC 4.3.5 is being released, adjusting target milestone.

[Matthias Klose (doko)]

Binary package hint: gcc-4.4

seen with a profiled build (make profile-opt
PROFILE_TASK='$(srcdir)/Lib/test/regrtest.py') building python-3.0rc3 on
i486-linux-gnu. Using pybench as the PROFILE_TASK doesn't show this bug).

gcc -pthread -c -fno-strict-aliasing -DNDEBUG -g -O2 -Wall -Wstrict-prototypes
-fprofile-use -I. -IInclude -I../Include -DPy_BUILD_CORE -o Modules/config.o
Modules/config.c
../Python/thread.c: In function 'PyThread_acquire_lock':
../Python/thread.c:419: error: corrupted profile info: number of executions for
edge 16-3 thought to be -1
../Python/thread.c:419: error: corrupted profile info: number of executions for
edge 16-17 thought to be 5657524
make[3]: *** [Python/thread.o] Error 1

[Matthias Klose (doko)]

tagging for armel (but not specific for armel). the current python2.6 build in maverick does build, but not python3.1 when using the profiled build.

[Barry Warsaw (barry)]

Fails on amd64 too, building _ssl.c

[Matthias Klose (doko)]

failed armel build (from ppa:doko/toolchain):
http://launchpadlibrarian.net/51573890/buildlog_ubuntu-maverick-armel.python3.2_3.2~~20100707-0ubuntu2_FAILEDTOBUILD.txt.gz

[Matthias Klose (doko)]

may turn into a blueprint on implementing profile guided optimization

[Matthias Klose (doko)]

no change on armel:

http://launchpadlibrarian.net/55247507/buildlog_ubuntu-maverick-armel.python3.2_3.2~a2-1ubuntu1~ppa2_FAILEDTOBUILD.txt.gz

[Loïc Minier (lool)]

(Not a Linaro-specific regression)

[Michael Hope (michaelh1)]

Note that this is not Linaro specific, but we plan to get PGO working for ARM this cycle:
 https://blueprints.launchpad.net/gcc-linaro/+spec/profiler-driven-feedback

Medium priority so might happen.

[Hubicka (hubicka)]

Richard's reorg of profiling to SSA uncovered some of issues with pure&const functions that are fixed in the current mainline. Can you, please, check if that solves your problem?

[Matthias Klose (doko)]

I ran into bug #47248 trying to build a recent snapshot.

[Ulrich Weigand (uweigand)]

I just successfully completed a profiled build of python3.2_3.2~b2-1.dsc on armel Natty using the Ubuntu/Linaro 4.5.1-10ubuntu3 system compiler, so the problem seems to no longer exist on 4.5.

Do we still care about 4.4 at this point?

[Matthias Klose (doko)]

the just uploaded python3.2_3.2~rc1-1ubuntu1 fails with the current Ubuntu/Linaro gcc-4.5 in natty on amd64, i386 and powerpc. armel is the only architecture which seems to build.

Building with gcc-4.6 from the ubuntu-toolchain-r/test ppa fails to build while running the setup.py with the just built python trying to build the extensions.

[Matthias Klose (doko)]

no, 4.4 is not interesting anymore for this issue.

[Matthias Klose (doko)]

with gcc-4.6 from the ~ubuntu-toolchain-r/test PPA I get (with the just built python (built with -fprofile-generate):

build-static$ ./python
XXX lineno: 1101, opcode: 0
Fatal Python error: Py_Initialize: Unable to get the locale encoding
Traceback (most recent call last):
  File "/home/packages/python/3.2/python3.2-3.2~rc1/build-static/../Lib/encodings/__init__.py", line 31, in <module>
XXX lineno: 39, opcode: 0
Aborted

[Matthias Klose (doko)]

trying to build python 3.2~rc1, I run into:

I get (with the just built python (built with -fprofile-generate):

build-static$ ./python
XXX lineno: 1101, opcode: 0
Fatal Python error: Py_Initialize: Unable to get the locale encoding
Traceback (most recent call last):
  File "/home/packages/python/3.2/python3.2-3.2~rc1/build-static/../Lib/encodings/__init__.py", line 31, in <module>
XXX lineno: 39, opcode: 0
Aborted

The build is ok with the normal build.

[Matthias Klose (doko)]

no, normal python build fails too, this is reported as bug #47271.

[Matthias Klose (doko)]

no, normal python build fails too, this is reported as upstream bug
http://gcc.gnu.org/bugzilla/show_bug.cgi?id=47271

[Matthias Klose (doko)]

hmm, can't set the status back to NEW, just to RESOLVED. ...

a normal build of 3.2rc1 succeeds with trunk r169142 and the proposed fix for PR47271.

the profiled build still fails with:

gcc-4.6 -pthread -c -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -fprofile-use -I. -IInclude -I../Include -DPy_BUILD_CORE -o Python/bltinmodule.o ../Python/bltinmodule.c
../Python/bltinmodule.c: In function 'builtin___build_class__':
../Python/bltinmodule.c:40:23: warning: variable 'nbases' set but not used [-Wunused-but-set-variable]
../Python/bltinmodule.c: In function 'builtin_exec':
../Python/bltinmodule.c:769:9: warning: variable 'plain' set but not used [-Wunused-but-set-variable]
gcc-4.6 -pthread -c -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -fprofile-use -I. -IInclude -I../Include -DPy_BUILD_CORE -o Python/ceval.o ../Python/ceval.c
../Python/ceval.c: In function 'PyEval_RestoreThread':
../Python/ceval.c:4472:1: error: corrupted profile info: profile data is not flow-consistent
../Python/ceval.c:4472:1: error: corrupted profile info: number of executions for edge 4-5 thought to be 2002859
../Python/ceval.c:4472:1: error: corrupted profile info: number of executions for edge 4-1 thought to be -9
make[3]: *** [Python/ceval.o] Error 1

[Matthias Klose (doko)]

 updated PR38292, still seen with trunk and the proposed fix for PR47271.

[Manu-gcc (manu-gcc)]

(In reply to comment #15)
> hmm, can't set the status back to NEW, just to RESOLVED. ...
>

You have to use your gcc account (I think).

[Ulrich Weigand (uweigand)]

I've now reproduced and analyzed the problem on i386 with GCC 4.5, i.e. building python3.2-3.2~rc1 using the 4.5.1-1ubuntu3 compiler.

It turns out that there is no particular bug here (the CFG looks identical in the -fprofile-generate and -fprofile-use cases), but instead we're running in a known limitation of the profiling code: it is not thread-safe.

This means that when using profiling in a multi-threaded application, profile counters may not be fully accurate since counter updates may have been skipped due to race conditions in accessing the counters.

This is consistent with the symptoms we're seeing: the problem disappears on my (single-core) ARM board, but is present on i386/amd64/ppc all of which presumably are built on multi-core machines, which increases the chance of actually running into one of those race conditions. The functions where the problem shows up likewise tend to be places where high thread contention is expected (e.g. synchronization primitives).

The recommended way to deal with this problem is to use the -fprofile-correction flag, which will employ heuristics to attempt to adjust incorrect counters, instead of simply aborting compilation. See the manual page:

       -fprofile-correction
           Profiles collected using an instrumented binary for multi-threaded
           programs may be inconsistent due to missed counter updates. When
           this option is specified, GCC will use heuristics to correct or
           smooth out such inconsistencies. By default, GCC will emit an error
           message when an inconsistent profile is detected.

I've added the -fprofile-correction flag to the build_all_use_profile rule in Makefile.pre.in, and with this change I was able to successfully build the package (only i386 tested).

The issues with 4.6 must be some other problem (note that the profiling code was significantly rewritten between 4.5 and 4.6, so we may well run into new problems here). I'll look into this next.

[Ulrich Weigand (uweigand)]

It turns out there is no other problem on 4.6. The compiler in the ubuntu-toolchain-r/test ppa does not build Python at all due to PR 47271. After adding the fix for this PR to the ppa package, the compiler runs into the exact same problem as described for 4.5 in the previous comment. By using -fprofile-correction as above, I was able to successfully build the python3.2-3.2~rc1 package with profile-directed feedback enabled (on i386).

So to summarize the problems discussed in this thread:

- GCC 4.6 had a regression where it failed to built Python at all. This is PR 47271, and is already fixed in mainline.

- GCC (any version!) uses thread-unsafe code to update profile counters, which means they can always be slightly wrong when profiling multi-threaded code, and therefore inconsistent with the flow graph. This will happen most frequently on multi-core machines, and in functions that experience high thread contention. The problem can be worked around using -fprofile-correction. Using this flag should enable profiled builds of Python with (at least) GCC 4.5 and 4.6.

[Michael Hope (michaelh1)]

Marked as wont-fix as the compiler is working as designed.

[Rguenth (rguenth)]

4.3 branch is being closed, moving to 4.4.7 target.

[Pinskia (pinskia)]

I don't think this is a regression now as we never had good thread support for gcov/profiling. That is we don't do atomic adds for the profiling.

[Rguenth (rguenth)]

We seem to miss a reproducer here.

[Jakub-gcc (jakub-gcc)]

4.4 branch is being closed, moving to 4.5.4 target.

[Doko-v (doko-v)]

the python builds works when built using -fprofile-correction