femtest.app.test_open.TestObjectOpen test fails on s390x in hirsute

However, it is an OOM.

[4828342.378424] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=lxc.payload.autopkgtest-lxd-cgruyr,mems_allowed=0,global_oom,task_memcg=/lxc.payload.autopkgtest-lxd-cgruyr,task=freecadcmd,pid=2459486,uid=1000000
[4828342.378434] Out of memory: Killed process 2459486 (freecadcmd) total-vm:2196220kB, anon-rss:1597084kB, file-rss:0kB, shmem-rss:0kB, UID:1000000 pgtables:3608kB oom_score_adj:0
[4828342.577608] oom_reaper: reaped process 2459486 (freecadcmd), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

I've found the same today and can confirm Brians report.

Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: Tasks state (memory values in pages):
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 728] 0 728 59674 239 108544 0 0 accounts-daemon
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 732] 103 732 2420 307 71680 0 -900 dbus-daemon
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 736] 0 736 20544 81 69632 0 0 irqbalance
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 737] 0 737 7568 1917 112640 0 0 networkd-dispat
...
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 67717] 1000 67717 2699 889 71680 0 0 bash
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 67765] 1000 67765 8764 789 126976 0 0 journalctl
Mar 15 11:17:28 cpaelzer-s390x-easyrdf kernel: [ 67771] 1000 67771 1456507 946756 8323072 0 0 freecadcmd

FYI, this is also broken the same way in Debian

https://ci.debian.net/packages/f/freecad/
https://ci.debian.net/data/autopkgtest/testing/s390x/f/freecad/10997677/log.gz

Before blindly marking it as big-tests (which is the first thought on an OOM) I wanted to check if it works with extra memory.
So I ensures I can reproduce in a guest:
2G: OOMs with 2G size
8G: OOMs with 8G size
...
This confirms similar tries that were done before.

So it seems the new version is really broken on s390x for now.
Unfortunately this is also tied into the opencascade migration atm.

Gladly Brian already reported that to Debian (see the linked deb-bug 984952)

So as we discussed on IRC the better way out might be:
  [12:27] <LocutusOfBorg> I was just saying that restoring and rebuilding previous
                          version might speed up the migration

But especially since cad@s390x isn't really an important case I wonder if it should really hold back the new version?

Upstream 19.1 doesn't list anything that sounds related
https://github.com/FreeCAD/FreeCAD/compare/0.19...0.19.1

One can run just the failing test and recreate the issue:
 $ freecadcmd --console --run-test femtest.app.test_open.TestObjectOpen

Checking consumption with that shows that it quickly goes up (2s interval)
$ pidstat -p $(pgrep freecadcmd) -T ALL -tr 2
Linux 5.10.0-14-generic (h-test) 03/15/21 _s390x_ (4 CPU)

11:47:08 UID TGID TID minflt/s majflt/s VSZ RSS %MEM Command
11:47:10 1000 19709 - 226433.50 0.00 1541952 1406260 17.10 freecadcmd
11:47:10 1000 - 19709 226418.50 0.00 1541952 1406260 17.10 |__freecadcmd

11:47:08 UID TGID TID minflt-nr majflt-nr Command
11:47:10 1000 19709 - 452867 0 freecadcmd
11:47:10 1000 - 19709 452837 0 |__freecadcmd

11:47:10 UID TGID TID minflt/s majflt/s VSZ RSS %MEM Command
11:47:12 1000 19709 - 326168.00 1.00 4949828 3360308 40.87 freecadcmd
11:47:12 1000 - 19709 326187.00 1.00 4949828 3360572 40.88 |__freecadcmd

11:47:10 UID TGID TID minflt-nr majflt-nr Command
11:47:12 1000 19709 - 652336 2 freecadcmd
11:47:12 1000 - 19709 652374 2 |__freecadcmd

11:47:12 UID TGID TID minflt/s majflt/s VSZ RSS %MEM Command
11:47:14 1000 19709 - 181738.00 0.00 4949828 4814156 58.56 freecadcmd
11:47:14 1000 - 19709 181719.00 0.00 4949828 4814156 58.56 |__freecadcmd

11:47:12 UID TGID TID minflt-nr majflt-nr Command
11:47:14 1000 19709 - 363476 0 freecadcmd
11:47:14 1000 - 19709 363438 0 |__freecadcmd

11:47:14 UID TGID TID minflt/s majflt/s VSZ RSS %MEM Command
11:47:16 1000 19709 - 0.00 0.00 4949828 4814156 58.56 freecadcmd
11:47:16 1000 - 19709 0.00 0.00 4949828 4814156 58.56 |__freecadcmd

11:47:14 UID TGID TID minflt-nr majflt-nr Command
11:47:16 1000 19709 - 0 0 freecadcmd
11:47:16 1000 - 19709 0 0 |__freecadcmd

11:47:16 UID TGID TID minflt/s majflt/s VSZ RSS %MEM Command
11:47:18 1000 19709 - 186463.00 0.00 8357704 6306020 76.70 freecadcmd
11:47:18 1000 - 19709 186476.50 0.00 8357704 6306020 76.70 |__freecadcmd

The test file backing this is at
  freecad-common: /usr/share/freecad/Mod/Fem/femtest/app/test_open.py

Checking the case with that I was able to derive that the mem-hog starts within

  self.document = FreeCAD.open(join(self.test_file_dir, "all_objects_de9b3fb438.FCStd"))

That is at
  freecad-common: /usr/share/freecad/Mod/Fem/femtest/data/open/all_objects_de9b3fb438.FCStd

The file format is a zip archive with this content:
12K ./thumbnails
416K .

I'd need to find and dbeug this open function if it does some big-endian flaw on calculating sizes.

It might be worth to note that all other tests work fine.
  Ran 535 tests in 41.895s

E.g. a file created with head as tested in test_femobjects_open_head works well.

Only the freecad file created with the older version fails.

TBH - given the state of cad@s390x I think we can leave it at the Debian report (maybe more a cad expert than me stabbing at it rather blindly), update there with this new insight and let them decide if it should go to upstream or not.

For the current state I'd think we could skip this subtest if running on s390x and thereby resolve the test issue for now.

With skip code applied

...
test_femobjects_open_de9b3fb438 (femtest.app.test_open.TestObjectOpen) ... ok
test_femobjects_open_head (femtest.app.test_open.TestObjectOpen) ... load master head document objects
import TestObjectCreate
import TestObjectType
Recompute......
Importing project files...... (100.0 %)
Postprocessing...... (100.0 %)
ok

----------------------------------------------------------------------
Ran 3 tests in 0.449s

OK

Submitted to Debian: https://salsa.debian.org/science-team/freecad/-/merge_requests/19

And updated on bug https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=984952

Debian accepted my fix and uploaded that in 0.19.1+dfsg1-1 which from upstream and Debian POV is a pure bugfix release. Therefore we should be ok to sync this in without an FFe.

But atm it is still building, so we have to wait a bit ...

This bug was fixed in the package freecad - 0.19.1+dfsg1-2

---------------
freecad (0.19.1+dfsg1-2) unstable; urgency=medium

  * Team upload.
  * [aed47c1] Fix whitespaces in previous commit from Christian Ehrhardt,
    breaking python autopkgtests

 -- Gianfranco Costamagna <email address hidden> Tue, 16 Mar 2021 17:55:02 +0100