{"action":"created","issue":{"url":"https://api.github.com/repos/NixOS/nixpkgs/issues/10828","labels_url":"https://api.github.com/repos/NixOS/nixpkgs/issues/10828/labels{/name}","comments_url":"https://api.github.com/repos/NixOS/nixpkgs/issues/10828/comments","events_url":"https://api.github.com/repos/NixOS/nixpkgs/issues/10828/events","html_url":"https://github.com/NixOS/nixpkgs/issues/10828","id":115113476,"number":10828,"title":"Hydra OOM NixOS test failures","user":{"login":"wizeman","id":168610,"avatar_url":"https://avatars.githubusercontent.com/u/168610?v=3","gravatar_id":"","url":"https://api.github.com/users/wizeman","html_url":"https://github.com/wizeman","followers_url":"https://api.github.com/users/wizeman/followers","following_url":"https://api.github.com/users/wizeman/following{/other_user}","gists_url":"https://api.github.com/users/wizeman/gists{/gist_id}","starred_url":"https://api.github.com/users/wizeman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wizeman/subscriptions","organizations_url":"https://api.github.com/users/wizeman/orgs","repos_url":"https://api.github.com/users/wizeman/repos","events_url":"https://api.github.com/users/wizeman/events{/privacy}","received_events_url":"https://api.github.com/users/wizeman/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-11-04T18:10:03Z","updated_at":"2015-12-01T18:09:17Z","closed_at":null,"body":"Sorry for the wall of text, but I took a look at recent Hydra NixOS test failures and after looking at it for some time, I believe I have found the root cause of a problem that has been plaguing us for a long time (months, at least).\r\n\r\nFor example, take a look at this test failure:\r\n\r\nhttps://hydra.nixos.org/build/27413932\r\n\r\nIt starts failing with this kernel stack trace:\r\n```\r\nmachine# [ 1176.832344] unionfs: page allocation failure: order:7, mode:0xc0d0\r\nmachine# [ 1176.834779] CPU: 0 PID: 869 Comm: unionfs Tainted: P           O    4.1.12 #1-NixOS\r\nmachine# [ 1176.836785] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014\r\nmachine# [ 1176.839576]  0000000000000007 ffff88002404fa28 ffffffff814d1486 ffff88002f611f38\r\nmachine# [ 1176.841455]  000000000000c0d0 ffff88002404fab8 ffffffff811553d8 0000000000000000\r\nmachine# [ 1176.843257]  0000000000000007 0000000000000040 ffff88002c270000 000000000000c0d0\r\nmachine# [ 1176.844909] Call Trace:\r\nmachine# [ 1176.845617]  [<ffffffff814d1486>] dump_stack+0x45/0x57\r\nmachine# [ 1176.846864]  [<ffffffff811553d8>] warn_alloc_failed+0xd8/0x130\r\nmachine# [ 1176.848176]  [<ffffffff8115811e>] ? __alloc_pages_direct_compact+0xee/0xf0\r\nmachine# [ 1176.849829]  [<ffffffff8115835d>] __alloc_pages_nodemask+0x23d/0xa50\r\nmachine# [ 1176.851069]  [<ffffffff81199151>] alloc_pages_current+0x91/0x110\r\nmachine# [ 1176.852444]  [<ffffffff8115552e>] alloc_kmem_pages+0xe/0x10\r\nmachine# [ 1176.853694]  [<ffffffff81170e18>] kmalloc_order+0x18/0x50\r\nmachine# [ 1176.855030]  [<ffffffff81171414>] kmalloc_order_trace+0x24/0xa0\r\nmachine# [ 1176.856749]  [<ffffffff811a3d51>] __kmalloc+0x111/0x1c0\r\nmachine# [ 1176.858247]  [<ffffffffa038ec13>] v9fs_dir_readdir_dotl+0x193/0x1c0 [9p]\r\nmachine# [ 1176.859977]  [<ffffffff811db384>] ? mntput+0x24/0x40\r\nmachine# [ 1176.861194]  [<ffffffff811c3d22>] ? path_cleanup+0x42/0x60\r\nmachine# [ 1176.862538]  [<ffffffff811ca793>] ? path_openat+0x93/0x630\r\nmachine# [ 1176.863788]  [<ffffffff811cc22f>] ? user_path_at_empty+0x5f/0xa0\r\nmachine# [ 1176.865087]  [<ffffffff811cebe7>] iterate_dir+0x97/0x130\r\nmachine# [ 1176.866248]  [<ffffffff811cf071>] SyS_getdents+0x81/0x100\r\nmachine# [ 1176.867329]  [<ffffffff811ced50>] ? fillonedir+0xd0/0xd0\r\nmachine# [ 1176.868544]  [<ffffffff814d6dee>] system_call_fastpath+0x12/0x71\r\n```\r\n\r\nThe problem here is that the kernel is trying to allocate a contiguous section of 2^7=128 pages, which is 512 KB. This is *way* too much: kernel pages tend to get fragmented over time and kernel developers often go to great lengths to try allocating at most only 1 contiguous page at a time whenever they can.\r\n\r\nFrom the error message, it looks like the culprit is unionfs, but this is misleading: unionfs is the name of the userspace process that was running when the system ran out of memory, but it wasn't unionfs who was allocating the memory: it was the kernel; specifically it was the `v9fs_dir_readdir_dotl()` function, which is the code for handling the `readdir()` function in the 9p filesystem (the filesystem that is used to share a directory structure between a qemu host and its VM).\r\n\r\nIf you look at the code, here's what it's doing at the moment it tries to allocate memory:\r\n```C\r\n    buflen = fid->clnt->msize - P9_IOHDRSZ;\r\n\r\n\trdir = v9fs_alloc_rdir_buf(file, buflen);\r\n```\r\n\r\nIf you look into `v9fs_alloc_rdir_buf()`, you will see that it will try to allocate a contiguous buffer of memory (using `kzalloc()`, which is a wrapper around `kmalloc()`) of size `buflen + 8 bytes` or so.\r\n\r\nSo in reality, this code actually allocates a buffer of size proportional to `fid->clnt->msize`.\r\nWhat is this `msize`? If you follow the definition of the structures, you will see that it's the negotiated buffer transfer size between 9p client and 9p server. On the client side, it can be controlled with the `msize` mount option.\r\n\r\nWhat this all means is that, the reason for running out of memory is that the code (which we can't easily change) tries to allocate a contiguous buffer of size more or less equal to \"`negotiated 9p protocol buffer size`\", which seems to be way too big (in our NixOS tests, at least).\r\n\r\nWhy is the negotiated 9p protocol buffer size so big in our tests? See this excerpt from our `nixos/modules/virtualisation/qemu-vm.nix` file:\r\n```nix\r\n        ${if cfg.writableStore then \"/nix/.ro-store\" else \"/nix/store\"} =\r\n          { device = \"store\";\r\n            fsType = \"9p\";\r\n            options = \"trans=virtio,version=9p2000.L,msize=1048576,cache=loose\";\r\n            neededForBoot = true;\r\n          };\r\n        \"/tmp/xchg\" =\r\n          { device = \"xchg\";\r\n            fsType = \"9p\";\r\n            options = \"trans=virtio,version=9p2000.L,msize=1048576,cache=loose\";\r\n            neededForBoot = true;\r\n          };\r\n        \"/tmp/shared\" =\r\n          { device = \"shared\";\r\n            fsType = \"9p\";\r\n            options = \"trans=virtio,version=9p2000.L,msize=1048576\";\r\n            neededForBoot = true;\r\n          };\r\n```\r\n\r\nAs you can see, it seems that we are manually setting the msize to 1048576 (even though the qemu 9p server seems to negotiate only up to 512KB).\r\n\r\nI think there are 2 possible fixes here:\r\n\r\n1. Increase the QEMU VM memory size for the Hydra tests. This can be a workaround, but I think it's bound to fail again soon in the future. \r\n\r\n   * From my experience, after an ordinary machine is up for some time it can be almost impossible to find 512 KB of contiguous memory available, even if you have several GBs of RAM and even if you have memory compaction enabled.\r\n\r\n   * Also, I've been observing these kind of 9p page allocation failures in Hydra tests for a long time now (months, at least), which we seem to try to fix by increasing the VM memory size, but even then they always seem to come back sooner or later.\r\n\r\n2. Decrease the `msize` parameter in the `qemu-vm.nix` file (to 128K or even less, or maybe take it out altogether and let the system choose a default value).\r\nThis has the side effect of making the tests slower (I don't know by how much), but at least I think they will be more reliable.\r\n\r\nWhat do you think?\r\n\r\n\r\n\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/NixOS/nixpkgs/issues/comments/161050700","html_url":"https://github.com/NixOS/nixpkgs/issues/10828#issuecomment-161050700","issue_url":"https://api.github.com/repos/NixOS/nixpkgs/issues/10828","id":161050700,"user":{"login":"jcumming","id":1982341,"avatar_url":"https://avatars.githubusercontent.com/u/1982341?v=3","gravatar_id":"","url":"https://api.github.com/users/jcumming","html_url":"https://github.com/jcumming","followers_url":"https://api.github.com/users/jcumming/followers","following_url":"https://api.github.com/users/jcumming/following{/other_user}","gists_url":"https://api.github.com/users/jcumming/gists{/gist_id}","starred_url":"https://api.github.com/users/jcumming/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jcumming/subscriptions","organizations_url":"https://api.github.com/users/jcumming/orgs","repos_url":"https://api.github.com/users/jcumming/repos","events_url":"https://api.github.com/users/jcumming/events{/privacy}","received_events_url":"https://api.github.com/users/jcumming/received_events","type":"User","site_admin":false},"created_at":"2015-12-01T18:09:17Z","updated_at":"2015-12-01T18:09:17Z","body":"@wizeman good detective work! "}}