[MDEV-30518] main.func_json_notembedded fails on s390x: outputs massive amount of text Created: 2023-01-31  Updated: 2023-10-09

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.11.5
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Otto Kekäläinen Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-27955 main.func_json_notembedded test fails... Closed

 Description   

While testing https://github.com/MariaDB/server/pull/2448 and doing builds on multiple architectures I noticed that on Launchpad the s390x build fails on:

...
main.mysqltest_tracking_info             w3 [ pass ]      1
main.negation_elimination                w1 [ pass ]      5
main.nested_profiling                    w3 [ pass ]      2
main.mysql                               w2 [ pass ]  107941
worker[4] Test still running: main.func_json_notembedded
worker[4] Test still running: main.func_json_notembedded
worker[4] Test still running: main.func_json_notembedded
worker[4] Test still running: main.func_json_notembedded
worker[4] Test still running: main.func_json_notembedded
worker[4] Trying to dump core for [mysqltest - pid: 41359, winpid: 41359]
worker[4] Trying to dump core for [mysqld.1 - pid: 40608, winpid: 40608]
main.func_json_notembedded               w4 [ fail ]  timeout after 7200 seconds
        Test ended at 2023-01-30 04:10:27
 
Test case timeout after 7200 seconds
 
== /<<PKGBUILDDIR>>/builddir/mysql-test/var/4/log/func_json_notembedded.log == 
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    2345678
]
select json_loose(@arr);
json_loose(@arr)
[1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 
...
1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 2345678]
select json_merge_patch(@obj, @obj);
 
 == /<<PKGBUILDDIR>>/builddir/mysql-test/var/4/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local server through socket '/<<PKGBUILDDIR>>/builddir/mysql-test/var/tm' (111)
 
 
 - saving '/<<PKGBUILDDIR>>/builddir/mysql-test/var/4/log/main.func_json_notembedded/' to '/<<PKGBUILDDIR>>/builddir/mysql-test/var/log/main.func_json_notembedded/'
 
Test main.func_json_notembedded has failed 2 times, no more retries!
 
***Warnings generated in error logs during shutdown after running tests: main.func_json_notembedded
 
Attempting backtrace. You can use the following information to find out
...
Completed: Failed 2/1030 tests, 99.81% were successful.
 
Failing test(s): main.func_json_notembedded
 
The log files in var/log may give you some hint of what went wrong.
 
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
Errors/warnings were found in logfiles during server shutdown after running the
following sequence(s) of tests:
    main.fulltext_distinct main.fulltext2 main.func_json_notembedded main.fulltext_derived_4257 main.func_digest main.func_if main.fulltext_derived_4316 main.func_json main.func_int main.func_bit main.func_in main.fulltext_multi main.frm_bad_row_type-7333 main.func_date_add main.fulltext_var main.fulltext3 main.flush_table main.func_isnull main.func_concat main.fulltext main.flush_ssl main.fulltext_update main.func_crypt main.func_encrypt_nossl main.func_default main.func_encrypt_ucs2 main.func_equal main.fulltext_cache main.fulltext_charsets main.fulltext_left_join main.func_des_encrypt main.func_group main.fulltext_order_by main.func_hybrid_type main.func_extract main.func_compress
    main.func_json_notembedded
161 tests were skipped, 63 by the test itself.
...

Full log at https://launchpadlibrarian.net/648708349/buildlog_ubuntu-lunar-s390x.mariadb_1%3A10.11.1-2~ubuntu23.04.1~1675043290.397d3975e3e.dev.otto_BUILDING.txt.gz

This seems a bit similar to MDEV-27955, MDEV-28714 and MDEV-24909 but none of them had this failure that it prints out the whole output, so filing this as a new bug.

I am aware that MariaDB Foundation might not care about s390x architecture, but often this kind of bugs reveal deeper problems, so it might be good to take a look. As an example the failure originally on armhf that lead to https://github.com/MariaDB/server/pull/2448 was at first just one architecture issue, but later revealed that the time code in question had not been updated in 10+ years and needed to be modernized for the sake of all architectures.



 Comments   
Comment by Otto Kekäläinen [ 2023-02-05 ]

In MDEV-27955 the test required too much memory or was too slow and timed out.

Time out happened again on hppa in https://buildd.debian.org/status/fetch.php?pkg=mariadb&arch=hppa&ver=1%3A10.11.1-2&stamp=1675231483&raw=0

Comment by Otto Kekäläinen [ 2023-02-05 ]

The test failure on ppc64 is probably also related as it crashes/timeouts on this same test:

Comment by Otto Kekäläinen [ 2023-02-10 ]

The same failure was now also seen on sparc64 in https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1030630

Comment by Ehsan Kiani Far [ 2023-07-25 ]

I tried to manually run this test on s390x and x64 by running this query:

set @obj=concat_ws('','{', repeat('"a":"b",', 1250000/2), '"c":"d"}');
set @arr=concat_ws('','[', repeat('1234567,', 1250000/2), '2345678]');
select length(@obj), length(@arr);
set max_statement_time=0.0001;
 
select json_array_append(@arr, '$[0]', 1);

on x64, the `select json_array_append(@arr, '$[0]', 1);` query results an error as expected since it takes much more that `max_statement_time` limit.
on s390x on the other hand, it completes the query and returns the result in about 0.137 (`1 row in set (0.137 sec)`) seconds which is much more that the configured `max_statement_time`. the logic for the expected behaviour was implemented in https://jira.mariadb.org/browse/MDEV-24909 issue with this PR: https://github.com/MariaDB/server/commit/7808cf9a8b4430262df23b6410de61c499ee740d
that implementation fixed the issue on x64 but that doesn't work on s390x. Any idea what might be wrong?

Comment by Otto Kekäläinen [ 2023-10-07 ]

I ran all tests on all available architectures at https://launchpad.net/~otto/+archive/ubuntu/mariadb/+builds?build_text=&build_state=all and this failure with long string of 1234567, 1234567, 1234567, 1234567... is still visible on multiple architectures.

Comment by Otto Kekäläinen [ 2023-10-09 ]

So it has been established that this is not s390x-specific, but can happen on multiple architectures. However for some reason it seems to be most frequent on s390x.

Output from https://launchpadlibrarian.net/691064783/buildlog_ubuntu-mantic-s390x.mariadb_1%3A10.11.5-3~bpo23.10.1~1696830433.49186426d72+feature.re.enable.all.tests_BUILDING.txt.gz

worker[1] Test still running: main.func_json_notembedded
worker[1] Test still running: main.func_json_notembedded
worker[1] Test still running: main.func_json_notembedded
worker[1] Test still running: main.func_json_notembedded
worker[1] Test still running: main.func_json_notembedded
worker[1] Trying to dump core for [mysqltest - pid: 262516, winpid: 262516]
worker[1] Trying to dump core for [mysqld.1 - pid: 261907, winpid: 261907]
main.func_json_notembedded               w1 [ fail ]  timeout after 7200 seconds
        Test ended at 2023-10-09 08:50:09
 
Test case timeout after 7200 seconds
 
== /<<PKGBUILDDIR>>/builddir/mysql-test/var/1/log/func_json_notembedded.log == 
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    1234567,
    2345678
]
select json_loose(@arr);
json_loose(@arr)
[1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567,
...
1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 2345678]
select json_merge(@obj, @arr);
json_merge(@obj, @arr)
[{"a": "b", "a": "b", "a": "b", "a": "b", "a": "b", "a": "b", "a": "b", "a": "b",
...
"b", "a": "b", "a": "b", "a": "b", "a": "b", "c": "d"}, 1234567, 1234567, 1234567, 1234567, 1234567,
...
1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 2345678]
select json_merge(@obj, @arr);
json_merge(@obj, @arr)
[{"a": "b", "a": "b", "a": "b", "a": "b", "a": "b",
...
"b", "a": "b", "a": "b", "c": "d"}, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567,
...
1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 1234567, 2345678]
select json_merge_patch(@obj, @obj);
 
 == /<<PKGBUILDDIR>>/builddir/mysql-test/var/1/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local server through socket '/<<PKGBUILDDIR>>/builddir/mysql-test/var/tm' (111)
 
 - skipping '/<<PKGBUILDDIR>>/builddir/mysql-test/var/1/log/main.func_json_notembedded/'
 
Test main.func_json_notembedded has failed 2 times, no more retries!
 
***Warnings generated in error logs during shutdown after running tests: main.func_json_notembedded
 
Attempting backtrace. You can use the following information to find out

No backtrace is printed though.

Generated at Thu Feb 08 10:16:50 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.