Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[Stu Redman]

Very well explained btkaos, but I'm afraid you are wrong.
- There is a sigsegv that is only visible when amule runs in gdb. Up to this everything is fine, only after this aMule creates events like mad and eats up all the mem.
- Your theory says in short, network events are still created, but not processed anymore. This would mean incoming data (plus a little overhead) would be stored in RAM instead of being flushed to disk. Well, the oom happens within a very short time after things start going wrong. Memory is eaten up much faster than you could download. And even if you are on a high speed line - if processing stops, no new blocks are requested from sources, and everything comes to a screeching halt.
- Where does the influence of the Kernel change fit into the picture?

[btkaos]

Well this is a proof of concept completely untested patch:

Code: [Select]

@@ -249,6 +265,10 @@ void CEMSocket::OnReceive(int nErrorCode)
                        // Update limit
                        if (ret >= downloadLimit) {
                                downloadLimit = 0;
+                               // We are above the read limit, avoid getting inputs until next turn.
+                               this->SetNotify(wxSOCKET_OUTPUT_FLAG |
+                                               wxSOCKET_CONNECTION_FLAG |
+                                               wxSOCKET_LOST_FLAG);
                        } else {
                                downloadLimit -= ret;
                        }
@@ -293,11 +313,16 @@ void CEMSocket::OnReceive(int nErrorCode)
 void CEMSocket::SetDownloadLimit(uint32 limit)
 {
        downloadLimit = limit;
        downloadLimitEnable = true;    

        // CPU load improvement
        if(limit > 0 && pendingOnReceive == true){
-               OnReceive(0);
+         // Reenable the socket
+         this->SetNotify(wxSOCKET_INPUT_FLAG  |
+                         wxSOCKET_OUTPUT_FLAG |
+                         wxSOCKET_CONNECTION_FLAG |
+                         wxSOCKET_LOST_FLAG);
+         OnReceive(0);
        }
 }
 

I will apply fuzzily due to all my modifications, but it should apply. I'm testing it right now

[Stu Redman]

If it fails please try:

Add the following in wx/socket.h to wxSocketBase (as public):

Code: [Select]

void * GetGSocket() const { return m_socket; }
Add a log line in CEMSocket::Destroy() and print GetGSocket() (which is available for CEMSocket since it derives from wxSocketBase).

Code: [Select]

AddLogLineN(CFormat(wxT("Destroyed GSocket %p")) % GetGSocket());
When you get the next crash, check the log if the GSocket involved was destroyed recently.

[btkaos]

- There is a sigsegv that is only visible when amule runs in gdb. Up to this everything is fine, only after this aMule creates events like mad and eats up all the mem.

I'm not seeing this sigsegv, and I'm running gdb all the time. I did see it but was due some bad interaction of connections getting dropped

Try it yourself, get a lot of downloads so you are able to download at very high speed, then limit amule to 10Kb/s download. See what happens.

- Your theory says in short, network events are still created, but not processed anymore. This would mean incoming data (plus a little overhead) would be stored in RAM instead of being flushed to disk.

My debugging shows that millions of events are being created and that no wx event processing takes place. The memory is being eaten by the events itself (see OnRequest in wx sources, socket.cpp and the code of AddPendingEvent). Indeed, a wxSocketEvent has quite a small memory footprint and uses not network data. The network data is store in kernel buffers.

Well, the oom happens within a very short time after things start going wrong. Memory is eaten up much faster than you could download.

Memory is eaten by wxSocketEvent objects. From my last crash: number of pending events: 1326118478.

And even if you are on a high speed line - if processing stops, no new blocks are requested from sources, and everything comes to a screeching halt.

Of course, when the OOM starts amule is not responsive, the app is trapped a loop. Indeed as you said, the OOM takes place in a very short time, it fills my 8Gb RAM in about 20/30 seconds. Indeed, log stops responding, etc...

Let me clarify that I have verified with debugging all what I said. What I'm not so sure is why glib never calls their idle handler anymore, I guess that is because 100% cpu use, but I'm not sure. However I have checked that this is what happens, my debugging shows g_main_iterate_context polling and creating new sockets events continuosly.

- Where does the influence of the Kernel change fit into the picture?

I can reproduce this with old kernels and all wx versions.

BTW, the patch doesn't work

[btkaos]

If it fails please try:

Add the following in wx/socket.h to wxSocketBase (as public):

Code: [Select]

void * GetGSocket() const { return m_socket; }
Add a log line in CEMSocket::Destroy() and print GetGSocket() (which is available for CEMSocket since it derives from wxSocketBase).

Code: [Select]

AddLogLineN(CFormat(wxT("Destroyed GSocket %p")) % GetGSocket());
When you get the next crash, check the log if the GSocket involved was destroyed recently.

STU, I'm not getting crashes, but OOM.

[btkaos]

Indeed, let me clarify that all my backtraces come from attaching gdb to a process going OOM. I have a "watcher" script to do this. I didn't get a crash "per se"

The crashes some other users seem to have could be attributed to two things:

• Glib/GTK are not safe with respect to out of memory conditions. In words of their main developer, handling gracefully OOM  would have been "too complicated" so instead let the program crash. X windows can do this, and of course is very expensive, given that you have cover every call to a function which may allocate memory. Nevermind techniques to do that transparently exist from more than 30 years, but it seems some developers were not very well versed.
• When this particular bug happens, wx event handling won't run, so socket cleanup, and some code which relies on events start malfunctioning.

[Stu Redman]

I get a Sigsev, normal memory consumption.

Code: [Select]

2011-01-10 23:52:33: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 215
 2011-01-10 23:52:37: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 208
 2011-01-10 23:52:40: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 3 TCQF 0 SO 15 EMS 220
 2011-01-10 23:52:44: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 220
 2011-01-10 23:52:47: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 214
 2011-01-10 23:52:50: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 222
 2011-01-10 23:52:54: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 230
 2011-01-10 23:52:58: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 229
 2011-01-10 23:53:02: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 0 TCQF 0 SO 15 EMS 212
 2011-01-10 23:53:05: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 220
 2011-01-10 23:53:24: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 7 TCQF 0 SO 15 EMS 216
 2011-01-10 23:53:24: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 7 TCQF 0 SO 15 EMS 216
 2011-01-10 23:53:24: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 7 TCQF 0 SO 15 EMS 216
 2011-01-10 23:53:24: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 7 TCQF 0 SO 15 EMS 216
 2011-01-10 23:53:26: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 39 CQF 0 TCQ 1 TCQF 0 SO 15 EMS 215
 2011-01-10 23:53:27: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 38 CQF 0 TCQ 0 TCQF 0 SO 15 EMS 186
 2011-01-10 23:53:29: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 3 CQF 10 TCQ 0 TCQF 0 SO 15 EMS 204
 2011-01-10 23:53:32: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 4 TCQF 0 SO 15 EMS 204
 2011-01-10 23:53:35: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 2 TCQF 0 SO 15 EMS 194
 2011-01-10 23:53:39: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 3 TCQF 0 SO 15 EMS 212
 2011-01-10 23:53:42: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 3 TCQF 1 SO 15 EMS 213
 2011-01-10 23:53:45: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 0 TCQF 0 SO 15 EMS 220
 2011-01-10 23:53:51: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 0 TCQF 2 SO 15 EMS 219
 2011-01-10 23:53:53: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 0 CQF 0 TCQ 3 TCQF 5 SO 15 EMS 226
 2011-01-10 23:53:56: UploadBandwidthThrottler.cpp(311): UBT: t 0 CQ 3 CQF 0 TCQ 1 TCQF 12 SO 15 EMS 235
 2011-01-10 23:53:59: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 8 CQF 23 TCQ 0 TCQF 31 SO 15 EMS 237
 2011-01-10 23:54:03: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 1 TCQF 84 SO 15 EMS 242
 2011-01-10 23:54:17: UploadBandwidthThrottler.cpp(311): UBT: t 2 CQ 0 CQF 0 TCQ 0 TCQF 106 SO 15 EMS 243
 2011-01-10 23:54:17: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 0 TCQF 106 SO 15 EMS 243
 2011-01-10 23:54:17: UploadBandwidthThrottler.cpp(311): UBT: t 2 CQ 0 CQF 0 TCQ 0 TCQF 106 SO 15 EMS 244
 2011-01-10 23:54:21: UploadBandwidthThrottler.cpp(311): UBT: t 5 CQ 0 CQF 0 TCQ 3 TCQF 124 SO 15 EMS 211
 2011-01-10 23:54:23: UploadBandwidthThrottler.cpp(311): UBT: t 17 CQ 0 CQF 0 TCQ 1 TCQF 134 SO 15 EMS 211
 2011-01-10 23:54:26: UploadBandwidthThrottler.cpp(311): UBT: t 1 CQ 0 CQF 0 TCQ 0 TCQF 184 SO 15 EMS 207
 2011-01-10 23:54:32: UploadBandwidthThrottler.cpp(311): UBT: t 6 CQ 0 CQF 0 TCQ 0 TCQF 194 SO 15 EMS 209
 2011-01-10 23:54:35: UploadBandwidthThrottler.cpp(311): UBT: t 2 CQ 0 CQF 0 TCQ 0 TCQF 302 SO 15 EMS 209
 2011-01-10 23:54:38: UploadBandwidthThrottler.cpp(311): UBT: t 3 CQ 0 CQF 0 TCQ 0 TCQF 386 SO 15 EMS 195
 2011-01-10 23:54:44: UploadBandwidthThrottler.cpp(311): UBT: t 5 CQ 0 CQF 0 TCQ 1 TCQF 460 SO 15 EMS 208
 2011-01-10 23:54:45: UploadBandwidthThrottler.cpp(311): UBT: t 4 CQ 3 CQF 0 TCQ 1 TCQF 518 SO 15 EMS 205
 2011-01-10 23:54:51: UploadBandwidthThrottler.cpp(311): UBT: t 7 CQ 0 CQF 0 TCQ 0 TCQF 552 SO 15 EMS 220
 2011-01-10 23:54:53: UploadBandwidthThrottler.cpp(311): UBT: t 7 CQ 0 CQF 0 TCQ 0 TCQF 563 SO 15 EMS 227
 2011-01-10 23:55:02: UploadBandwidthThrottler.cpp(311): UBT: t 9 CQ 0 CQF 0 TCQ 0 TCQF 695 SO 15 EMS 231
 2011-01-10 23:55:02: UploadBandwidthThrottler.cpp(311): UBT: t 7 CQ 0 CQF 0 TCQ 0 TCQF 695 SO 15 EMS 231
 2011-01-10 23:55:06: UploadBandwidthThrottler.cpp(311): UBT: t 8 CQ 0 CQF 0 TCQ 0 TCQF 705 SO 15 EMS 232
 2011-01-10 23:55:33: UploadBandwidthThrottler.cpp(311): UBT: t 4 CQ 0 CQF 0 TCQ 0 TCQF 724 SO 15 EMS 228
 2011-01-10 23:55:33: UploadBandwidthThrottler.cpp(311): UBT: t 5 CQ 0 CQF 0 TCQ 0 TCQF 724 SO 15 EMS 228
 2011-01-10 23:55:33: UploadBandwidthThrottler.cpp(311): UBT: t 9 CQ 0 CQF 0 TCQ 0 TCQF 724 SO 15 EMS 228
 2011-01-10 23:55:33: UploadBandwidthThrottler.cpp(311): UBT: t 8 CQ 0 CQF 0 TCQ 0 TCQF 724 SO 15 EMS 228
 2011-01-10 23:55:36: UploadBandwidthThrottler.cpp(311): UBT: t 14 CQ 0 CQF 0 TCQ 1 TCQF 732 SO 15 EMS 207
 2011-01-10 23:55:38: UploadBandwidthThrottler.cpp(311): UBT: t 8 CQ 0 CQF 0 TCQ 0 TCQF 759 SO 15 EMS 156
 2011-01-10 23:55:44: UploadBandwidthThrottler.cpp(311): UBT: t 11 CQ 0 CQF 0 TCQ 0 TCQF 829 SO 15 EMS 163


Code: [Select]

(gdb) bt
#0  __pthread_mutex_lock (mutex=0x7) at pthread_mutex_lock.c:50
#1  0x00007ffff29d004f in g_source_destroy_internal (source=0x7fffe6398db0, context=0xffffffffffffffff, have_lock=0) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:942
#2  0x00007ffff29d290e in g_source_remove (tag=<value optimized out>) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:1717
#3  0x00007ffff67fcc7d in GSocketGUIFunctionsTableConcrete::Uninstall_Callback (this=0x7ffff6ccabb0, socket=0x2b2eda0, event=GSOCK_OUTPUT) at ./src/gtk/gsockgtk.cpp:119
#4  0x00007ffff63c37ef in GSocket::Disable (this=0x2b2eda0, event=GSOCK_OUTPUT) at ./src/unix/gsocket.cpp:1527
#5  0x00007ffff63c42f8 in GSocket::Detected_Write (this=0x2b2eda0) at ./src/unix/gsocket.cpp:1836
#6  0x00007ffff67fca1c in _GSocket_GDK_Input (data=0x2b2eda0, source=82, condition=GDK_INPUT_WRITE) at ./src/gtk/gsockgtk.cpp:41
#7  0x00007ffff478e99f in gdk_io_invoke (source=<value optimized out>, condition=<value optimized out>, data=<value optimized out>)
    at /build/buildd/gtk+2.0-2.22.0/gdk/gdkevents.c:1082
#8  0x00007ffff29d0342 in g_main_dispatch (context=0xc67ed0) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:2149
#9  g_main_context_dispatch (context=0xc67ed0) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:2702
#10 0x00007ffff29d42a8 in g_main_context_iterate (context=0xc67ed0, block=<value optimized out>, dispatch=<value optimized out>, self=<value optimized out>)
    at /build/buildd/glib2.0-2.26.1/glib/gmain.c:2780
#11 0x00007ffff29d47b5 in g_main_loop_run (loop=0x1cb17a0) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:2988
#12 0x00007ffff4b4d3e7 in IA__gtk_main () at /build/buildd/gtk+2.0-2.22.0/gtk/gtkmain.c:1237
#13 0x00007ffff67faa5f in wxEventLoop::Run (this=0x1c9ca80) at ./src/gtk/evtloop.cpp:76
#14 0x00007ffff6896cc8 in wxAppBase::MainLoop (this=0xc67930) at ./src/common/appcmn.cpp:312
#15 0x00007ffff6896e42 in wxAppBase::OnRun (this=0xc67930) at ./src/common/appcmn.cpp:367
#16 0x00007ffff606ae5b in wxEntry (argc=@0x7ffff638f4b0, argv=0xc56dd0) at ./src/common/init.cpp:448
#17 0x00007ffff606af31 in wxEntry (argc=@0x7fffffffe0bc, argv=0x7fffffffe1a8) at ./src/common/init.cpp:460
#18 0x00000000005d04c2 in main (argc=1, argv=0x1) at amule-gui.cpp:93


I didn't get a crash "per se"

 

[Stu Redman]

For the fun of it - does it have an influence if you disable "show extended info on category tabs" ?

[btkaos]

Yes I'm aware of this post but quicly saw that this was an exceptional instance. I guess I should have posted about it. Note that this was an isolated crash.

Now I understand the problem, look at the value of the glib's context. Indeed it seems like an overflow of events glib's loop or something like that:

Code: [Select]

#1  0x00007ffff29d004f in g_source_destroy_internal (source=0x7fffe6398db0, context=0xffffffffffffffff, have_lock=0) at /build/buildd/glib2.0-2.26.1/glib/gmain.c:942


Code: [Select]

static void
g_source_destroy_internal (GSource      *source,
   GMainContext *context,
   gboolean      have_lock)
{
  if (!have_lock)
    LOCK_CONTEXT (context);
Boom here, as context is incorrect. As context is derived from source this seems like a glib bug (not the first time) or some bad interaction of wveventloop not running. Anyways the context returned by g_main_context_default was very wrong here.

I didn't get a crash for the last days.

Sorry for the confusion, STU. I guess you should try to reproduce it. Get a lots of sources and limit the download.
Regards,
BTK

[btkaos]

For the fun of it - does it have an influence if you disable "show extended info on category tabs" ?

Ok I'll try it, I see how that setting may interact weirly.

Patch I'm trying right now, changing line 307 of app.cpp from

Code: [Select]

    wxTheApp->m_idleTag = g_idle_add_full(G_PRIORITY_LOW, wxapp_idle_callback, NULL, NULL);


Code: [Select]

    wxTheApp->m_idleTag = g_idle_add_full(G_PRIORITY_HIGH, wxapp_idle_callback, NULL, NULL);
This should make the event loop of wx higher priority than the events coming from sockets. Too early to tell if it works.

[btkaos]

Patch I'm trying right now, changing line 307 of app.cpp from

Code: [Select]

    wxTheApp->m_idleTag = g_idle_add_full(G_PRIORITY_LOW, wxapp_idle_callback, NULL, NULL);


Code: [Select]

    wxTheApp->m_idleTag = g_idle_add_full(G_PRIORITY_HIGH, wxapp_idle_callback, NULL, NULL);
This should make the event loop of wx higher priority than the events coming from sockets. Too early to tell if it works.

Well, as I suspected that change didn't work, it starves the rest of the application with the timer events once aMule eats a lot of CPU.
Rebuilding wx and I'll try STU suggestion next.

[Stu Redman]

btkaos, I don't believe the problem is the events are not processed. Problem is rather they are generated at an insane, inexplicable rate.
Your patch disabling events didn't work. Does it work if you disable events altogether using Notify(false) instead of SetNotify() ?

[btkaos]

btkaos, I don't believe the problem is the events are not processed. Problem is rather they are generated at an insane, inexplicable rate.

I have confirmed that once the rate of events starts going up, wx event handing is starved. I started suspecting an event problem when AddLogLineN stopped working. You may believe it, but I have experimental data that shows otherwise.

Once you reproduce the bug, stop aMule when it has just eaten some hundredths of Mb. Then place a breakpoint in wxapp_idle_callback. You'll see that it is never called.
You may want to add some printf to wxapp_idle_callback instead. Keep in mind that AddLogLine doesn't work once the bug shows, as we have no event processing.

Your patch disabling events didn't work. Does it work if you disable events altogether using Notify(false) instead of SetNotify() ?

With that patch we will lose loss of connection events and so on, so it is not feasible. The problem is not how to disable events, but where and when. Anyways given the nature of the problem a more intrusive fix may be needed. It would be great if some developer could reproduce it. So far we have 3 users confirming that disabling the donwload limit solves the OOM.

[btkaos]

Problem is rather they are generated at an insane, inexplicable rate.

I believe I did explain that. Lots of data is coming and aMule doesn't read it because of download limit. Also if we read from a socket and there's data remaining another event will occur.

What is difficult to understand is why glib generates events for a socket if there's an event pending to be handled. Well, wx always accepts it, that's the problem. So from glib POV the event has been handled, from wx POV not yet, but glib feels free to emit another event. Once we reach an event rate enough to starve wx event processing, BOOM.

It seems the bug is then in wx socket code. IMHO when accepting a glib event, wx should tell glib to not report that kind of events again. When the wx event is served, it should enable it again. This is standard in event based programming.

[btkaos]

BTW, disabling "show extended info on category tabs"  didn't have any effect.