[Bug debuginfod/29982] New: sqlite errors when searching

[Bug debuginfod/29982] New: sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

            Bug ID: 29982
           Summary: sqlite errors when searching
           Product: elfutils
           Version: unspecified
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: debuginfod
          Assignee: unassigned at sourceware dot org
          Reporter: ross at burtonini dot com
                CC: elfutils-devel at sourceware dot org
  Target Milestone: ---

When debuginfod services as request, I often get a slew of errors:

[Tue Jan 10 10:42:51 2023] (2548256/2548514): fts traversed source paths in
0.232152s, scanned=6011, regex-skipped=0
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548742): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548543): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548565): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548612): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548742): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548565): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548543): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548612): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548742): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548543): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548565): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548742): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548612): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548742): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548565): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548543): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548612): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548565): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548517): sqlite3 error: sqlite3 step:
database table is locked
[Tue Jan 10 10:43:06 2023] (2548256/2548512): 127.0.0.1:49176
UA:elfutils/0.188,Linux/aarch64,ubuntu/22.04 XFF: GET
/buildid/db3c770eb4309ec5e8c43669407b98619a1f061a/debuginfo 200 28488 0+9ms

This is with an in-memory database.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #1 from Ross Burton <ross at burtonini dot com> ---
Obviously attaching a gdb and breaking on the error path magically fixes it for
me...

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fche at redhat dot com
     Ever confirmed|0                           |1
   Last reconfirmed|                            |2023-01-10
             Status|UNCONFIRMED                 |WAITING

--- Comment #2 from Frank Ch. Eigler <fche at redhat dot com> ---
Please supply a command line invocation for us to try to reproduce this, along
with version numbers of ubuntu / debuginfod / sqlite3.  This could happen if
the database is actually a normal file instead of :memory:, and two separate
debuginfod instances are trying to write to the same one.

(debuginfod -d :memory: is already tested on debian etc. as a part of the
testsuite.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #3 from Ross Burton <ross at burtonini dot com> ---
I can replicate with elfutils 0.188 and sqlite 3.40.1 on debian and ubuntu. Due
to previously discussed concurrency issues my commandline is essentially
-d:memory -c256 -C256.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #4 from Ross Burton <ross at burtonini dot com> ---
Just replicated with -c2 -C2.

Potentially of interest is that the log shows two PIDs:

[Tue Jan 10 11:32:20 2023] (2619858/2619864): sqlite3 error: sqlite3 step:
database table is locked
[repeated ~60 times]
[Tue Jan 10 11:32:20 2023] (2619858/2619860): 192.168.7.2:54292
UA:elfutils/0.188,Linux/aarch64,/ XFF: GET
/buildid/7fd4aae416bbcee8fd24cf5db0e805cd0c1e218e/debuginfo 200 3195072 0+122ms

The errors come from a different thread to that which handled the request.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #5 from Ross Burton <ross at burtonini dot com> ---
Note that the errors are just logged, the lookup still works, so it's possible
that your tests work but the logs are full of these messages.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #6 from Frank Ch. Eigler <fche at redhat dot com> ---
Please confirm the complete command line.

% debuginfod -d:memory

creates a file named ":memory", not an in-memory sqlite database alias
":memory:")

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #7 from Ross Burton <ross at burtonini dot com> ---
        cmd = [
            os.path.join(native_sysroot, "usr", "bin", "debuginfod"),
            "--verbose",
            "--database=:memory:",
            "--concurrency=2",
            "--connection-pool=2",
            get_bb_var("DEPLOY_DIR"),
        ]

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #8 from Ross Burton <ross at burtonini dot com> ---
Replicated with -vvvv:
[Tue Jan 10 11:43:35 2023] (2679838/2679844): searching for sources for
cu=../sysdeps/aarch64/crtn.S comp_dir=/usr/src/debug/g
libc/2.36-r0/csu #files=2 #dirs=2
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/bits/types/FILE.h
dup
[Tue Jan 10 11:43:35 2023] (2679838/2679844):
/usr/src/debug/glibc/2.36-r0/csu/../sysdeps/aarch64/crtn.S new
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/c++/12.2.0/cstdlib
dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/include/c++/12.2.0/bits/std_abs.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/sys/types.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/bits/types/time_t.h
dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/stdlib.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/bits/stdlib-float.h
dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/include/bits/stdlib-bsearch.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/bits/stdlib.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/c++/12.2.0/stdlib.h
dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/include/hashtab.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/include/obstack.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/libcpp/include/symtab.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/libcpp/internal.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/libcpp/include/cpplib.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/iconv.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/libcpp/include/mkdeps.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/string.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845): /usr/include/libintl.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/include/libiberty.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/src/debug/gcc/12.2.0-r0/libcpp/<built-in> dup
[Tue Jan 10 11:43:35 2023] (2679838/2679845):
/usr/include/c++/12.2.0/aarch64-poky-linux/bits/c++config.h dup
[Tue Jan 10 11:43:35 2023] (2679838/2679844): rpm-buildid-intern bind
1=34c56faac74aa9ce0b7bb21f772b4aa35f0be2f8
[Tue Jan 10 11:43:35 2023] (2679838/2679844): rpm-buildid-intern
step-ok-done(database table is locked) insert or ignore into buildids9_buildids
VALUES (NULL, ?);

Is the problem that it's still scanning the RPMs?

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #9 from Frank Ch. Eigler <fche at redhat dot com> ---
Perhaps a complete highly verbose trace (-vvv) would help identify the cause.
Scanning threads should not be able to lock each other out for O(1sec) from
sqlite operations in normal circumstances.  OTOH, one can rest assured that in
case of such sqlite problems, debuginfod just treats them as transient and
retries the related scan operation later.  Webapi service threads  do not
contend with the others at all, so clients don't see these transient errors.

-- 
You are receiving this mail because:
You are on the CC list for the bug.

[Bug debuginfod/29982] sqlite errors when searching

[ross at burtonini dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=29982

--- Comment #10 from Ross Burton <ross at burtonini dot com> ---
Created attachment 14569
  --> https://sourceware.org/bugzilla/attachment.cgi?id=14569&action=edit
Log

Attached is a log (6MB zstd compressed, 171M uncompressed...) with the step
locked errors, using -vvvvv to get the sqlite operation logging.

-- 
You are receiving this mail because:
You are on the CC list for the bug.