OpenPrinting / ipp-usb

ipp-usb -- HTTP reverse proxy, backed by IPP-over-USB connection to device
BSD 2-Clause "Simplified" License
129 stars 11 forks source link

OOM triggered due to high virtual memory usage by ipp-usb #43

Closed EMlyDinEsHMG closed 12 months ago

EMlyDinEsHMG commented 2 years ago

Hi!

We are using ipp-usb in our yocto based linux in arm platform for providing external printing feature using ipp protocol. It was working fine with HP printers(other brands have issues either not being detected or not responding to ipp req). Recently we have been seeing oom killer getting triggered in our device. When we check the back trace, we have found one observation is that ipp-usb vm memory is really high compared to available in RAM so we wanted to understand, and clarify if there is any issue. We have only 512MB RAM without swap. I am attaching the back trace we got from kernel log for the oom killing. Please check, and share if there any issue from ipp-usb with respect to vm usage (though rss memory is not high). We are using latest ipp-usb available which 0.9.19-2.

Please any help would be really appreciated from these logs.

Thanks PS: Let me know if anything else is required.

2022-03-04T10:11:54.107177Z,BTL200068500133,4,1,kernel:, [77776.905633] pidof invoked oom-killer: gfp_mask=0x800d0, order=0, oom_score_adj=0 2022-03-04T10:11:54.108703Z,BTL200068500133,4,1,kernel:, [77776.905652] CPU: 0 PID: 19236 Comm: pidof Tainted: G O 4.1.46 #5 2022-03-04T10:11:54.108779Z,BTL200068500133,4,1,kernel:, [77776.905662] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree) 2022-03-04T10:11:54.108844Z,BTL200068500133,4,1,kernel:, [77776.905668] Backtrace: 2022-03-04T10:11:54.108907Z,BTL200068500133,4,1,kernel:, [77776.905695] [<800132e4>] (dump_backtrace) from [<80013500>] (show_stack+0x18/0x1c) 2022-03-04T10:11:54.108970Z,BTL200068500133,4,1,kernel:, [77776.905702] r7:00000000 r6:80a81a70 r5:600d0113 r4:00000000 2022-03-04T10:11:54.109030Z,BTL200068500133,4,1,kernel:, [77776.905725] [<800134e8>] (show_stack) from [<8076475c>] (dump_stack+0x98/0xb4) 2022-03-04T10:11:54.109089Z,BTL200068500133,4,1,kernel:, [77776.905739] [<807646c4>] (dump_stack) from [<800b9f04>] (dump_header+0xa0/0x1c4) 2022-03-04T10:11:54.109150Z,BTL200068500133,4,1,kernel:, [77776.905745] r7:8d4ef390 r6:00000000 r5:000800d0 r4:00000000 2022-03-04T10:11:54.109209Z,BTL200068500133,4,1,kernel:, [77776.905765] [<800b9e64>] (dump_header) from [<800ba81c>] (oom_kill_process+0x400/0x480) 2022-03-04T10:11:54.109267Z,BTL200068500133,4,1,kernel:, [77776.905771] r10:00000000 r9:000800d0 r8:00000131 r7:8d4ef390 r6:8d4ef394 r5:00000000 2022-03-04T10:11:54.109325Z,BTL200068500133,4,1,kernel:, [77776.905790] r4:8d4eef80 2022-03-04T10:11:54.109381Z,BTL200068500133,4,1,kernel:, [77776.905802] [<800ba41c>] (oom_kill_process) from [<800baae8>] (out_of_memory+0x24c/0x3ac) 2022-03-04T10:11:54.109437Z,BTL200068500133,4,1,kernel:, [77776.905807] r10:80a6e1a8 r9:00000000 r8:00000000 r7:000800d0 r6:0001f022 r5:00000000 2022-03-04T10:11:54.109496Z,BTL200068500133,4,1,kernel:, [77776.905824] r4:8eed9ad4 2022-03-04T10:11:54.109556Z,BTL200068500133,4,1,kernel:, [77776.905835] [<800ba89c>] (out_of_memory) from [<800baea0>] (out_of_memory+0x58/0x78) 2022-03-04T10:11:54.109614Z,BTL200068500133,4,1,kernel:, [77776.905841] r10:00000040 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:000800d0 2022-03-04T10:11:54.116327Z,BTL200068500133,4,1,kernel:, [77776.905856] r4:80abda80 2022-03-04T10:11:54.116425Z,BTL200068500133,4,1,kernel:, [77776.905870] [<800bae48>] (out_of_memory) from [<800bf464>] (alloc_pages_nodemask+0x784/0x868) 2022-03-04T10:11:54.116489Z,BTL200068500133,4,1,kernel:, [77776.905875] r8:8f6e7900 r7:00000000 r6:80a6aab4 r5:00000000 r4:000800d0 2022-03-04T10:11:54.116552Z,BTL200068500133,4,1,kernel:, [77776.905897] [<800bece0>] (alloc_pages_nodemask) from [<800bf560>] (get_free_pages+0x18/0x34) 2022-03-04T10:11:54.117714Z,BTL200068500133,4,1,kernel:, [77776.905902] r10:00000400 r9:8f39d020 r8:8d7cbf5c r7:00000400 r6:000d88b0 r5:8f39d020 2022-03-04T10:11:54.117822Z,BTL200068500133,4,1,kernel:, [77776.905918] r4:00000000 2022-03-04T10:11:54.117894Z,BTL200068500133,4,1,kernel:, [77776.905932] [<800bf548>] (get_free_pages) from [<801549b4>] (proc_pid_readlink+0x60/0x110) 2022-03-04T10:11:54.117959Z,BTL200068500133,4,1,kernel:, [77776.905946] [<80154954>] (proc_pid_readlink) from [<800fc49c>] (SyS_readlinkat+0x9c/0xe8) 2022-03-04T10:11:54.118018Z,BTL200068500133,4,1,kernel:, [77776.905951] r7:7eb03748 r6:ffffff9c r5:00004000 r4:ffffffea 2022-03-04T10:11:54.118076Z,BTL200068500133,4,1,kernel:, [77776.905969] [<800fc400>] (SyS_readlinkat) from [<800fc508>] (SyS_readlink+0x20/0x24) 2022-03-04T10:11:54.118133Z,BTL200068500133,4,1,kernel:, [77776.905974] r10:00001200 r9:8d7ca000 r8:8000fb24 r7:00000055 r6:00000000 r5:000d88b0 2022-03-04T10:11:54.125706Z,BTL200068500133,4,1,kernel:, [77776.905990] r4:00000400 2022-03-04T10:11:54.125840Z,BTL200068500133,4,1,kernel:, [77776.906004] [<800fc4e8>] (SyS_readlink) from [<8000fb00>] (__sys_trace_return+0x0/0x20) 2022-03-04T10:11:54.125901Z,BTL200068500133,4,1,kernel:, [77776.906010] Mem-Info: 2022-03-04T10:11:54.125956Z,BTL200068500133,4,1,kernel:, [77776.906028] active_anon:50769 inactive_anon:6613 isolated_anon:0 2022-03-04T10:11:54.126003Z,BTL200068500133,4,1,kernel:, [77776.906028] active_file:194 inactive_file:199 isolated_file:0 2022-03-04T10:11:54.126054Z,BTL200068500133,4,1,kernel:, [77776.906028] unevictable:16 dirty:1 writeback:0 unstable:0 2022-03-04T10:11:54.126099Z,BTL200068500133,4,1,kernel:, [77776.906028] slab_reclaimable:1064 slab_unreclaimable:2320 2022-03-04T10:11:54.126149Z,BTL200068500133,4,1,kernel:, [77776.906028] mapped:7008 shmem:7774 pagetables:626 bounce:0 2022-03-04T10:11:54.126195Z,BTL200068500133,4,1,kernel:, [77776.906028] free:20094 free_pcp:0 free_cma:19620 2022-03-04T10:11:54.126243Z,BTL200068500133,4,1,kernel:, [77776.906062] Normal free:80376kB min:1980kB low:2472kB high:2968kB active_anon:203076kB inactive_anon:26452kB active_file:776kB inactive_file:796kB unevictable:64kB isolated(anon):0kB isolated(file):0kB present:524288kB managed:508040kB mlocked:64kB dirty:4kB writeback:0kB mapped:28032kB shmem:31096kB slab_reclaimable:4256kB slab_unreclaimable:9280kB kernel_stack:1136kB pagetables:2504kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:78480kB writeback_tmp:0kB pages_scanned:9504 all_unreclaimable? yes 2022-03-04T10:11:54.126294Z,BTL200068500133,4,1,kernel:, [77776.906068] lowmem_reserve[]: 0 0 0 2022-03-04T10:11:54.126342Z,BTL200068500133,4,1,kernel:, [77776.906078] Normal: 4514kB (UEMRC) 3198kB (UEMRC) 17816kB (UERC) 11332kB (UERC) 2564kB (C) 13128kB (C) 9256kB (C) 1512kB (C) 41024kB (C) 52048kB (C) 12*4096kB (C) = 80388kB 2022-03-04T10:11:54.126388Z,BTL200068500133,4,1,kernel:, [77776.906127] 8175 total pagecache pages 2022-03-04T10:11:54.126435Z,BTL200068500133,4,1,kernel:, [77776.906134] 0 pages in swap cache 2022-03-04T10:11:54.126481Z,BTL200068500133,4,1,kernel:, [77776.906140] Swap cache stats: add 0, delete 0, find 0/0 2022-03-04T10:11:54.131536Z,BTL200068500133,4,1,kernel:, [77776.906145] Free swap = 0kB 2022-03-04T10:11:54.131667Z,BTL200068500133,4,1,kernel:, [77776.906150] Total swap = 0kB 2022-03-04T10:11:54.131727Z,BTL200068500133,4,1,kernel:, [77776.906155] 131072 pages RAM 2022-03-04T10:11:54.131778Z,BTL200068500133,4,1,kernel:, [77776.906161] 0 pages HighMem/MovableOnly 2022-03-04T10:11:54.131830Z,BTL200068500133,4,1,kernel:, [77776.906165] 4294905822 pages reserved 2022-03-04T10:11:54.131878Z,BTL200068500133,4,1,kernel:, [77776.906170] 65536 pages cma reserved 2022-03-04T10:11:54.131925Z,BTL200068500133,6,1,kernel:, [77776.906175] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name 2022-03-04T10:11:54.131974Z,BTL200068500133,6,1,kernel:, [77776.906195] [ 103] 0 103 686 53 5 0 0 0 systemd-journal 2022-03-04T10:11:54.132020Z,BTL200068500133,6,1,kernel:, [77776.906206] [ 117] 0 117 2701 126 8 0 0 -1000 systemd-udevd 2022-03-04T10:11:54.132069Z,BTL200068500133,6,1,kernel:, [77776.906219] [ 233] 0 233 935 13 4 0 0 0 psplash-btl 2022-03-04T10:11:54.132117Z,BTL200068500133,6,1,kernel:, [77776.906229] [ 284] 0 284 758 126 5 0 0 0 crond 2022-03-04T10:11:54.132165Z,BTL200068500133,6,1,kernel:, [77776.906243] [ 285] 0 285 9976 260 14 0 0 0 ModemManager 2022-03-04T10:11:54.132210Z,BTL200068500133,6,1,kernel:, [77776.906252] [ 286] 0 286 678 18 5 0 0 0 klogd 2022-03-04T10:11:54.132256Z,BTL200068500133,6,1,kernel:, [77776.906261] [ 288] 0 288 10814 209 14 0 0 0 rsyslogd 2022-03-04T10:11:54.132302Z,BTL200068500133,6,1,kernel:, [77776.906272] [ 292] 799 292 1147 108 6 0 0 -900 dbus-daemon 2022-03-04T10:11:54.132347Z,BTL200068500133,6,1,kernel:, [77776.906281] [ 313] 0 313 758 50 5 0 0 0 systemd-logind 2022-03-04T10:11:54.132395Z,BTL200068500133,6,1,kernel:, [77776.906291] [ 348] 793 348 17562 716 19 0 0 0 polkitd 2022-03-04T10:11:54.132440Z,BTL200068500133,6,1,kernel:, [77776.906300] [ 350] 0 350 1324 78 7 0 0 0 login 2022-03-04T10:11:54.132489Z,BTL200068500133,6,1,kernel:, [77776.906310] [ 354] 0 354 1522 99 6 0 0 0 connmand 2022-03-04T10:11:54.132534Z,BTL200068500133,6,1,kernel:, [77776.906320] [ 362] 798 362 1249 85 6 0 0 0 avahi-daemon 2022-03-04T10:11:54.132580Z,BTL200068500133,6,1,kernel:, [77776.906329] [ 377] 798 377 1213 47 6 0 0 0 avahi-daemon 2022-03-04T10:11:54.132625Z,BTL200068500133,6,1,kernel:, [77776.906339] [ 397] 0 397 1799 122 6 0 0 0 wpa_supplicant 2022-03-04T10:11:54.132670Z,BTL200068500133,6,1,kernel:, [77776.906348] [ 722] 998 722 689 27 4 0 0 0 mgm.sh 2022-03-04T10:11:54.132715Z,BTL200068500133,6,1,kernel:, [77776.906357] [ 742] 998 742 3824 119 7 0 0 0 MGM 2022-03-04T10:11:54.132761Z,BTL200068500133,6,1,kernel:, [77776.906368] [ 773] 0 773 7376 93 9 0 0 0 pcscd 2022-03-04T10:11:54.148846Z,BTL200068500133,6,1,kernel:, [77776.906378] [ 914] 0 914 1221 118 6 0 0 0 systemd 2022-03-04T10:11:54.148937Z,BTL200068500133,6,1,kernel:, [77776.906387] [ 917] 0 917 1845 260 8 0 0 0 (sd-pam) 2022-03-04T10:11:54.148994Z,BTL200068500133,6,1,kernel:, [77776.906399] [ 921] 0 921 772 63 5 0 0 0 sh 2022-03-04T10:11:54.149043Z,BTL200068500133,6,1,kernel:, [77776.906409] [ 1191] 0 1191 689 35 4 0 0 0 bash 2022-03-04T10:11:54.155121Z,BTL200068500133,6,1,kernel:, [77776.906418] [ 1249] 0 1249 4173 421 12 0 0 0 processmonitor 2022-03-04T10:11:54.155214Z,BTL200068500133,6,1,kernel:, [77776.906429] [ 1252] 804 1252 126058 38611 210 0 0 0 ui 2022-03-04T10:11:54.155267Z,BTL200068500133,6,1,kernel:, [77776.906439] [ 1253] 803 1253 19780 8009 36 0 0 0 storagemanager 2022-03-04T10:11:54.155323Z,BTL200068500133,6,1,kernel:, [77776.906448] [ 1254] 800 1254 12671 4663 26 0 0 0 controller 2022-03-04T10:11:54.155371Z,BTL200068500133,6,1,kernel:, [77776.906461] [ 1255] 801 1255 28016 6741 54 0 0 0 acquisition 2022-03-04T10:11:54.155419Z,BTL200068500133,6,1,kernel:, [77776.906470] [ 1256] 802 1256 18767 7277 37 0 0 0 printer 2022-03-04T10:11:54.155465Z,BTL200068500133,6,1,kernel:, [77776.906479] [ 1257] 805 1257 9108 3088 22 0 0 0 cmsclienthandle 2022-03-04T10:11:54.155510Z,BTL200068500133,6,1,kernel:, [77776.906490] [ 1258] 0 1258 7793 1614 16 0 0 0 servicehandler 2022-03-04T10:11:54.155555Z,BTL200068500133,6,1,kernel:, [77776.906500] [20269] 0 20269 690 49 6 0 0 0 bash 2022-03-04T10:11:54.155601Z,BTL200068500133,6,1,kernel:, [77776.906509] [20270] 0 20270 690 15 5 0 0 0 bash 2022-03-04T10:11:54.155650Z,BTL200068500133,6,1,kernel:, [77776.906521] [20272] 0 20272 748 70 5 0 0 0 top 2022-03-04T10:11:54.155697Z,BTL200068500133,6,1,kernel:, [77776.906531] [17990] 0 17990 4529 298 9 0 0 0 cupsd 2022-03-04T10:11:54.155745Z,BTL200068500133,6,1,kernel:, [77776.906540] [18164] 0 18164 219571 241 18 0 0 0 ipp-usb 2022-03-04T10:11:54.155793Z,BTL200068500133,6,1,kernel:, [77776.906551] [19236] 0 19236 554 23 4 0 0 0 pidof 2022-03-04T10:11:54.155839Z,BTL200068500133,3,1,kernel:, [77776.906559] Out of memory: Kill process 1252 (ui) score 305 or sacrifice child

alexpevzner commented 2 years ago

Hi @EMlyDinEsHMG !

I will look to this problem.

alexpevzner commented 2 years ago

Hi @EMlyDinEsHMG,

Go programs' executable size is huge, because Go always links everything statically. It makes virtual memory consumption to be large. But is is only the virtual address space, not the real memory, Actual memory consumption, indicated by RSS, depends on program behaviour and for ipp-usb is not very large (less that for the ippusbxd, for example).

So for now, I don't see that ipp-usb causes any real problem.

EMlyDinEsHMG commented 2 years ago

Hi! @alexpevzner

Thanks for the response. Is there any estimate like how much ipp-usb will take if only one external USB printer is connected for printing, and used? Also we have one concern that is there requirement from ipp-usb requiring contiguous memory (how much if its) ? As we are thinking it could be due to memory fragmentation as well.

Please share your side insight about ipp-usb we have requested above (even we have attached logs of kernel backtrace) so that we can root cause the issue.

Thanks

EMlyDinEsHMG commented 1 year ago

Hi!

Thanks for your response. As you mentioned actual resident memory will depend on behaviour, what could be the max rss usage we can expect if we use single printer?

Thanks

Get Outlook for Androidhttps://aka.ms/AAb9ysg


From: Alexander Pevzner @.> Sent: Saturday, March 12, 2022 6:49:38 PM To: OpenPrinting/ipp-usb @.> Cc: EMlyDinEsHMG @.>; Mention @.> Subject: Re: [OpenPrinting/ipp-usb] OOM triggered due to high virtual memory usage by ipp-usb (Issue #43)

Hi @EMlyDinEsHMGhttps://github.com/EMlyDinEsHMG,

Go programs' executable size is huge, because Go always links everything statically. It makes virtual memory consumption to be large. But is is only the virtual address space, not the real memory, Actual memory consumption, indicated by RSS, depends on program behaviour and for ipp-usb is not very large (less that for the ippusbxd, for example).

So for now, I don't see that ipp-usb causes any real problem.

— Reply to this email directly, view it on GitHubhttps://github.com/OpenPrinting/ipp-usb/issues/43#issuecomment-1065882383, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AASUMHOJCAQOLPGFJ2DZKTTU7SKWVANCNFSM5QRQDFLA. Triage notifications on the go with GitHub Mobile for iOShttps://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Androidhttps://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub. You are receiving this because you were mentioned.Message ID: @.***>

alexpevzner commented 12 months ago

Looks like issue is outside of this project scope...