Closed Bug 1254780 Opened 6 years ago Closed 6 years ago

log_types is huge (408 KiB)

Categories

(Core :: WebRTC: Networking, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla48
Tracking Status
firefox48 --- fixed
Blocking Flags:
backlog tech-debt

People

(Reporter: n.nethercote, Assigned: n.nethercote)

References

Details

(Whiteboard: [MemShrink:P3])

Attachments

(1 file)

By far the biggest static data symbol in libxul is nrappkit's |log_types|. It's 408 KiB! And that contributes to the memory usage of every Firefox process.

The relevant code:

> #define NR_REG_MAX_NR_REGISTRY_LEN     128
> 
> typedef char NR_registry[NR_REG_MAX_NR_REGISTRY_LEN];
> 
> #define LOG_NUM_DESTINATIONS 3
> 
> typedef struct log_type_ {
>      char *facility_name;
>      int level[LOG_NUM_DESTINATIONS];
>      NR_registry dest_facility_key[LOG_NUM_DESTINATIONS];
> } log_type;
> 
> #define MAX_LOG_TYPES 1024
> 
> static log_type log_types[MAX_LOG_TYPES];

I don't know much about this code, but statically allocating 1024 of these things seems... generous. Perhaps it would be more suitable to use heap allocation, and start off with a smallish array -- 4 or 8 elements? -- and then resize it on demand?

I'd be happy to try implementing that, or I could let someone else who knows more about this code do it. ekr, what do you think?
Flags: needinfo?(ekr)
glandium identified that because log_types is zeroed, it's in the .bss section, and so it doesn't get paged into physical memory until it's touched. I confirmed that with smaps -- original I had this for libxul's .bss:

> Size:                764 kB
> Rss:                 276 kB

and then I changed log_types from 1024 entries to 4 just as a test and got this:

> Size:                360 kB
> Rss:                 276 kB

So it saves some address space but doesn't reduce physical memory usage at all. Bummer.
> So it saves some address space but doesn't reduce physical memory usage at
> all. Bummer.

Not surprising; as you'd expect almost all of those are unused, so they eat address space, and maybe one 4K-ish page in memory (and perhaps then only if logging is enabled with env vars).
I think it would be fine to change it to 32 or something, but it also doesn't sound
like it adds much value.
Flags: needinfo?(ekr)
Whiteboard: [MemShrink] → [MemShrink:P3]
I'd like to do this if only so that log_types doesn't forever sit at the top of
the static data size table in bug 1254777. 16 entries still seems generous and
gets it down from 408 KiB.
Attachment #8728767 - Flags: review?(ekr)
Assignee: nobody → n.nethercote
Status: NEW → ASSIGNED
> 16 entries still seems generous and gets it down from 408 KiB.

And I meant to add "to 6.4 KiB, which is #125 in the table".
backlog: --- → tech-debt
ekr: 2 week review ping for a 1 line patch.
Comment on attachment 8728767 [details] [diff] [review]
Shrink log_types from 1024 entries to 16

Review of attachment 8728767 [details] [diff] [review]:
-----------------------------------------------------------------

Based on c1, it doesn't seem like this has any significant operational impact on Firefox, it's just annoying when you look at the list. Is that correct? If so, it seems like an unnecessary change.
Attachment #8728767 - Flags: review?(ekr)
It only saves address space. But on Win32 crashes due to running out of address space are a reasonably significant fraction of all crashes, so it buys us 402 KiB of extra headroom there.
Comment on attachment 8728767 [details] [diff] [review]
Shrink log_types from 1024 entries to 16

Review of attachment 8728767 [details] [diff] [review]:
-----------------------------------------------------------------

Based on c1, it doesn't seem like this has any significant operational impact on Firefox, it's just annoying when you look at the list. Is that correct? If so, it seems like an unnecessary change.
Attachment #8728767 - Flags: review+
Backed out because it seems to cause crashes in Windows 7 debug developer tools tests.

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/964a638d77fa

Jobs with crashes:
https://treeherder.mozilla.org/logviewer.html#?job_id=24525745&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=24526640&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=24532451&repo=mozilla-inbound

01:49:51  WARNING -  PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::gfx::Log<1,mozilla::gfx::CriticalLogger>::WriteLog(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &)]
01:49:51     INFO -  Crash dump filename: c:\users\cltbld\appdata\local\temp\tmpqjk4w3.mozrunner\minidumps\8f0a54da-9c94-41e5-a3b4-bfd9a99d1845.dmp
01:49:51     INFO -  Operating system: Windows NT
01:49:51     INFO -                    6.1.7601 Service Pack 1
01:49:51     INFO -  CPU: x86
01:49:51     INFO -       GenuineIntel family 6 model 30 stepping 5
01:49:51     INFO -       8 CPUs
01:49:51     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
01:49:51     INFO -  Crash address: 0x5ee16df7
01:49:51     INFO -  Assertion: Unknown assertion type 0x00000000
01:49:51     INFO -  Process uptime: 54 seconds
01:49:51     INFO -  Thread 39 (crashed)
01:49:51     INFO -   0  xul.dll!mozilla::gfx::Log<1,mozilla::gfx::CriticalLogger>::WriteLog(std::basic_string<char,std::char_traits<char>,std::allocator<char> > const &) [Logging.h:5081a75fbe8c : 512 + 0x22]
01:49:51     INFO -      eip = 0x5ee16df7   esp = 0x0612f5fc   ebp = 0x0612f600   ebx = 0x0ddb40c0
01:49:51     INFO -      esi = 0x00000200   edi = 0x00000005   eax = 0x61aa8d5c   ecx = 0x68d50ad9
01:49:51     INFO -      edx = 0x00935279   efl = 0x00000206
01:49:51     INFO -      Found by: given as instruction pointer in context
01:49:51     INFO -   1  xul.dll!mozilla::gfx::Log<1,mozilla::gfx::CriticalLogger>::Flush() [Logging.h:5081a75fbe8c : 282 + 0xb]
01:49:51     INFO -      eip = 0x5ee12820   esp = 0x0612f608   ebp = 0x0612f648
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   2  xul.dll!mozilla::layers::AsyncTransactionWaiter::WaitComplete() [AsyncTransactionTracker.cpp:5081a75fbe8c : 39 + 0x26]
01:49:51     INFO -      eip = 0x5ef737f4   esp = 0x0612f650   ebp = 0x0612f71c
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   3  xul.dll!mozilla::layers::ImageBridgeChild::FlushAllImages(mozilla::layers::ImageClient *,mozilla::layers::ImageContainer *) [ImageBridgeChild.cpp:5081a75fbe8c : 665 + 0xf]
01:49:51     INFO -      eip = 0x5ef841c5   esp = 0x0612f724   ebp = 0x0612f73c
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   4  xul.dll!mozilla::layers::ImageContainer::ClearAllImages() [ImageContainer.cpp:5081a75fbe8c : 282 + 0x9]
01:49:51     INFO -      eip = 0x5eebd159   esp = 0x0612f744   ebp = 0x0612f758
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   5  xul.dll!mozilla::VideoFrameContainer::ClearCurrentFrame() [VideoFrameContainer.cpp:5081a75fbe8c : 95 + 0xf]
01:49:51     INFO -      eip = 0x5fc75cd6   esp = 0x0612f760   ebp = 0x0612f774
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   6  xul.dll!mozilla::MediaFormatReader::ReleaseMediaResources() [MediaFormatReader.cpp:5081a75fbe8c : 1624 + 0xc]
01:49:51     INFO -      eip = 0x5fc354f3   esp = 0x0612f77c   ebp = 0x0612f790
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   7  xul.dll!mozilla::MediaDecoderReader::Shutdown() [MediaDecoderReader.cpp:5081a75fbe8c : 370 + 0x7]
01:49:51     INFO -      eip = 0x5fc430df   esp = 0x0612f784   ebp = 0x0612f790
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   8  xul.dll!mozilla::MediaFormatReader::Shutdown() [MediaFormatReader.cpp:5081a75fbe8c : 141 + 0xa]
01:49:51     INFO -      eip = 0x5fc43616   esp = 0x0612f798   ebp = 0x0612f7a8
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -   9  xul.dll!mozilla::detail::MethodCallInvokeHelper<RefPtr<mozilla::MozPromise<bool,bool,0> >,mozilla::MediaDecoderReader>(RefPtr<mozilla::MozPromise<bool,bool,0> > ( mozilla::MediaDecoderReader::*)(void),mozilla::MediaDecoderReader *,mozilla::Tuple<> &,mozilla::IndexSequence<>) [MozPromise.h:5081a75fbe8c : 917 + 0xb]
01:49:51     INFO -      eip = 0x5fbdf5e9   esp = 0x0612f7b0   ebp = 0x0612f7bc
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  10  xul.dll!mozilla::detail::MethodCall<mozilla::MozPromise<bool,bool,0>,mozilla::MediaDecoderReader>::Invoke() [MozPromise.h:5081a75fbe8c : 942 + 0x19]
01:49:51     INFO -      eip = 0x5fc25eb9   esp = 0x0612f7c4   ebp = 0x0612f7dc
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  11  xul.dll!mozilla::detail::ProxyRunnable<mozilla::MozPromise<bool,bool,0>,mozilla::MediaDecoderReader>::Run() [MozPromise.h:5081a75fbe8c : 960 + 0x16]
01:49:51     INFO -      eip = 0x5fc3c859   esp = 0x0612f7e4   ebp = 0x0612f7f0
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  12  xul.dll!mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run() [TaskDispatcher.h:5081a75fbe8c : 192 + 0x1d]
01:49:51     INFO -      eip = 0x5e517d34   esp = 0x0612f7f8   ebp = 0x0612f808
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  13  xul.dll!mozilla::TaskQueue::Runner::Run() [TaskQueue.cpp:5081a75fbe8c : 171 + 0xe]
01:49:51     INFO -      eip = 0x5e517c01   esp = 0x0612f810   ebp = 0x0612f868
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  14  xul.dll!nsThreadPool::Run() [nsThreadPool.cpp:5081a75fbe8c : 228 + 0xe]
01:49:51     INFO -      eip = 0x5e5184e0   esp = 0x0612f870   ebp = 0x0612f8b4
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  15  xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:5081a75fbe8c : 994 + 0xe]
01:49:51     INFO -      eip = 0x5e51546d   esp = 0x0612f8bc   ebp = 0x0612f99c
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  16  xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:5081a75fbe8c : 297 + 0xd]
01:49:51     INFO -      eip = 0x5e54404c   esp = 0x0612f9a4   ebp = 0x0612f9b0
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  17  xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [MessagePump.cpp:5081a75fbe8c : 361 + 0xa]
01:49:51     INFO -      eip = 0x5e815ee5   esp = 0x0612f9b8   ebp = 0x0612f9dc
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  18  xul.dll!MessageLoop::RunInternal() [message_loop.cc:5081a75fbe8c : 234 + 0xf]
01:49:51     INFO -      eip = 0x5e7e4053   esp = 0x0612f9e4   ebp = 0x0612f9fc
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  19  xul.dll!MessageLoop::RunHandler() [message_loop.cc:5081a75fbe8c : 227 + 0x5]
01:49:51     INFO -      eip = 0x5e7e400b   esp = 0x0612fa04   ebp = 0x0612fa30
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  20  xul.dll!MessageLoop::Run() [message_loop.cc:5081a75fbe8c : 201 + 0x7]
01:49:51     INFO -      eip = 0x5e7e3d55   esp = 0x0612fa38   ebp = 0x0612fa50
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  21  xul.dll!nsThread::ThreadFunc(void *) [nsThread.cpp:5081a75fbe8c : 396 + 0xc]
01:49:51     INFO -      eip = 0x5e51a9c5   esp = 0x0612fa58   ebp = 0x0612fa90
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  22  nss3.dll!_PR_NativeRunThread [pruthr.c:5081a75fbe8c : 397 + 0x6]
01:49:51     INFO -      eip = 0x67f2594f   esp = 0x0612fa98   ebp = 0x0612fab0
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  23  nss3.dll!pr_root [w95thred.c:5081a75fbe8c : 95 + 0xa]
01:49:51     INFO -      eip = 0x67f1998f   esp = 0x0612fab8   ebp = 0x0612fabc
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  24  msvcr120.dll!_callthreadstartex [threadex.c : 376 + 0x6]
01:49:51     INFO -      eip = 0x68d5c01d   esp = 0x0612fac4   ebp = 0x0612faf4
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  25  msvcr120.dll + 0x2c001
01:49:51     INFO -      eip = 0x68d5c001   esp = 0x0612fafc   ebp = 0x0612fb00
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  26  kernel32.dll!BaseThreadInitThunk + 0x12
01:49:51     INFO -      eip = 0x765b3c45   esp = 0x0612fb08   ebp = 0x0612fb0c
01:49:51     INFO -      Found by: previous frame's frame pointer
01:49:51     INFO -  27  ntdll.dll!__RtlUserThreadStart + 0x27
01:49:51     INFO -      eip = 0x77f237f5   esp = 0x0612fb14   ebp = 0x0612fb4c
01:49:51     INFO -      Found by: call frame info
01:49:51     INFO -  28  ntdll.dll!_RtlUserThreadStart + 0x1b
01:49:51     INFO -      eip = 0x77f237c8   esp = 0x0612fb54   ebp = 0x0612fb64
01:49:51     INFO -      Found by: call frame info
Flags: needinfo?(n.nethercote)
> Backed out because it seems to cause crashes in Windows 7 debug developer
> tools tests.
> 
> Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/964a638d77fa

> 01:49:51  WARNING -  PROCESS-CRASH | Main app process exited normally |
> application crashed [@
> mozilla::gfx::Log<1,mozilla::gfx::CriticalLogger>::WriteLog(std::
> basic_string<char,std::char_traits<char>,std::allocator<char> > const &)]

I can't possibly imagine how this change could cause gfx logging assertion failures.  A full search of c/cpp/h files finds log_types are only used in rlog.c, and MAX_LOG_TYPES the same (so no linkage collisions).
I was also surprised. No matter; I'll do some try runs early next week and reland if the backout was unnecessary.
Flags: needinfo?(n.nethercote)
Sorry for the backout, I searched newer Win 7 debug dt runs and found 2 crashes of that type from tests run after the backout:

https://treeherder.mozilla.org/logviewer.html#?job_id=24586823&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=24573263&repo=mozilla-inbound

Please reland the patch.
> Please reland the patch.

Will do. Thank you for checking.
https://hg.mozilla.org/mozilla-central/rev/98dd6cb59d8e
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla48
You need to log in before you can comment on or make changes to this bug.