node 0.7.9-pre cpu 100% on ubuntu 64bit

[cnzoupeng]

root@li413-184:~# node -v
v0.7.9-pre

//--important part of my codes

var app = express.createServer();
// Configuration

app.configure(function(){
  app.set('views', __dirname + '/views');
  app.set('view engine', 'jade');
  app.use(express.bodyParser());
  app.use(express.methodOverride());
  app.use(express.cookieParser());
  app.use(express.session({ secret: 'itQuan' }));
  //app.use(loginAuth(mysqlcli));
  app.use(express.static(__dirname + '/public'));
  app.use(app.router);
  app.use(express.errorHandler({showStack: true, dumpExceptions: true}));
});

app.get('/*', function(req, res){
    res.render('404',{status: 404,
        title:'404 - File Not Found'});
});


app.listen(server_port, function(){
    console.log('Node server start:  ' + server_port);
});

//------------------------------------
after i execute "node server.js" 30 seconds the cpu up to 100%, but no http request
this is the stack info

(gdb) info thread
  Id   Target Id         Frame 
  2    Thread 0x7ff64499a700 (LWP 17125) "SignalSender" 0x00007ff64395bfd0 in sem_wait ()
   from /lib/x86_64-linux-gnu/libpthread.so.0
* 1    Thread 0x7ff64499c740 (LWP 17124) "node" 0x00007ff64367f6d9 in syscall ()
   from /lib/x86_64-linux-gnu/libc.so.6

(gdb) bt
#0  0x00007ff64367f6d9 in syscall () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000005bf06e in get_clock () at ../deps/uv/src/unix/ev/ev.c:781
#2  time_update (max_block=<optimized out>, loop=0xe11740) at ../deps/uv/src/unix/ev/ev.c:2334
#3  ev_run (loop=0xe11740, flags=<optimized out>) at ../deps/uv/src/unix/ev/ev.c:2505
#4  0x00000000005b4f6d in uv__poll (block=<optimized out>, loop=0xe10a80) at ../deps/uv/src/unix/core.c:201
#5  uv__run (loop=0xe10a80) at ../deps/uv/src/unix/core.c:221
#6  0x00000000005b5370 in uv_run (loop=0xe10a80) at ../deps/uv/src/unix/core.c:232
#7  0x00000000005734f7 in node::Start(int, char**) ()
#8  0x00007ff6435b276d in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6
#9  0x0000000000569969 in _start ()
(gdb) bt
#0  0x00007ff64367f6d9 in syscall () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x00000000005bf06e in get_clock () at ../deps/uv/src/unix/ev/ev.c:781
#2  time_update (max_block=<optimized out>, loop=0xe11740) at ../deps/uv/src/unix/ev/ev.c:2334
#3  ev_run (loop=0xe11740, flags=<optimized out>) at ../deps/uv/src/unix/ev/ev.c:2505
#4  0x00000000005b4f6d in uv__poll (block=<optimized out>, loop=0xe10a80) at ../deps/uv/src/unix/core.c:201
#5  uv__run (loop=0xe10a80) at ../deps/uv/src/unix/core.c:221
#6  0x00000000005b5370 in uv_run (loop=0xe10a80) at ../deps/uv/src/unix/core.c:232
#7  0x00000000005734f7 in node::Start(int, char**) ()
#8  0x00007ff6435b276d in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6
#9  0x0000000000569969 in _start ()

(gdb) thread 2
[Switching to thread 2 (Thread 0x7ff64499a700 (LWP 17125))]
#0  0x00007ff64395bfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007ff64395bfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000009337fd in v8::internal::LinuxSemaphore::Wait() ()
#2  0x000000000086cfa1 in v8::internal::RuntimeProfilerRateLimiter::SuspendIfNecessary() ()
#3  0x0000000000933bfe in v8::internal::SignalSender::Run() ()
#4  0x00000000009338ee in v8::internal::ThreadEntry(void*) ()
#5  0x00007ff643955e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#6  0x00007ff6436834bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#7  0x0000000000000000 in ?? ()
(gdb) bt
#0  0x00007ff64395bfd0 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000009337fd in v8::internal::LinuxSemaphore::Wait() ()
#2  0x000000000086cfa1 in v8::internal::RuntimeProfilerRateLimiter::SuspendIfNecessary() ()
#3  0x0000000000933bfe in v8::internal::SignalSender::Run() ()
#4  0x00000000009338ee in v8::internal::ThreadEntry(void*) ()
#5  0x00007ff643955e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#6  0x00007ff6436834bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#7  0x0000000000000000 in ?? ()

[bnoordhuis]

Thanks for the report. Do you see the same behavior with a server that doesn't use express? I want to rule out the possibility of a bug in third-party modules (i.e. express).

[pixelspark]

I got something similar today when testing an existing codebase (that used to work just fine on node 0.7.3) with the latest 0.7.9-pre (git cloned from the master branch). It happens both on OS X and Linux. On Linux, after a while it starts repeating the following lines when running with strace and using 100% CPU (during which the application works fine by the way):

clock_gettime(CLOCK_MONOTONIC, {31126308, 775254165}) = 0
clock_gettime(CLOCK_MONOTONIC, {31126308, 775292894}) = 0
epoll_wait(3, {}, 64, 0) = 0

The strange thing is that all worker processes (4 on the Mac, 2 on the Linux machine) go to 100% CPU usage.

[bnoordhuis]

@pixelspark Can you post a test case or describe how and what your application does (e.g. which node subsystems it uses and how)? The busy loop looks like node thinks there are pending events when there are none (hence the zero timeout to epoll_wait).

[pixelspark]

The following code will make the node process consume 100% CPU (one core) on my Mac (with 0.7.9-pre) after the first HTTP request has been made to localhost:6283:

var HTTP = require("http");
var System = require("util");

System.puts("server starting");

var server = HTTP.createServer(function(request, response) {
});

server.listen(6283,"localhost", function() {
    System.puts("Server running");
});

[pixelspark]

DTrace (dtruss node script.js) shows the following line repeating a zillion times after the first HTTP request:

kevent(0x3, 0x100A17B40, 0x0)        = 0 0

(The first occurrence has 0x1 instead of 0x0 for the third parameter to kevent)

[bnoordhuis]

Okay, confirmed. Thanks.

[bnoordhuis]

Fixed in 0fd2834. Thanks for the bug reports, people.