muduo tcp服务端日志分析

[root@localhost bin]# ./echoserver_unittest
20170831 13:05:22.436148Z 21969 INFO  pid = 21969, tid = 21969 - EchoServer_unittest.cc:73
20170831 13:05:22.436463Z 21969 INFO  sizeof TcpConnection = 236 - EchoServer_unittest.cc:74
20170831 13:05:22.896780Z 21969 TRACE EPollPoller epollfd_ = 3 - EPollPoller.cc:45
20170831 13:05:23.093016Z 21969 TRACE Channel fd_ = 4 - Channel.cc:35
20170831 13:05:23.093063Z 21969 TRACE Channel loop_ = 0xBF84DF30 - Channel.cc:36
20170831 13:05:23.093076Z 21969 TRACE TimerQueue timerfd_ = 4 - TimerQueue.cc:102
20170831 13:05:23.093954Z 21969 TRACE updateChannel fd = 4 events = 3 index = -1 - EPollPoller.cc:113
20170831 13:05:23.167919Z 21969 TRACE update epoll_ctl op = ADD fd = 4 event = { 4: IN PRI  } - EPollPoller.cc:181
20170831 13:05:23.168017Z 21969 TRACE Channel fd_ = 5 - Channel.cc:35
20170831 13:05:23.168037Z 21969 TRACE Channel loop_ = 0xBF84DF30 - Channel.cc:36
20170831 13:05:23.190017Z 21969 DEBUG EventLoop EventLoop created 0xBF84DF30 in thread 21969 - EventLoop.cc:76
20170831 13:05:23.190154Z 21969 TRACE EventLoop wakeupFd_ = 5 in thread 21969 - EventLoop.cc:77
20170831 13:05:23.190209Z 21969 TRACE updateChannel fd = 5 events = 3 index = -1 - EPollPoller.cc:113
20170831 13:05:23.191581Z 21969 TRACE update epoll_ctl op = ADD fd = 5 event = { 5: IN PRI  } - EPollPoller.cc:181
20170831 13:05:23.191776Z 21969 TRACE Channel fd_ = 6 - Channel.cc:35
20170831 13:05:23.191795Z 21969 TRACE Channel loop_ = 0xBF84DF30 - Channel.cc:36
20170831 13:05:23.191848Z 21969 TRACE Acceptor acceptSocket_.fd = 6 - Acceptor.cc:34
20170831 13:05:23.246882Z 21969 TRACE updateChannel fd = 6 events = 3 index = -1 - EPollPoller.cc:113
20170831 13:05:23.246970Z 21969 TRACE update epoll_ctl op = ADD fd = 6 event = { 6: IN PRI  } - EPollPoller.cc:181
20170831 13:05:23.247002Z 21969 TRACE loop EventLoop 0xBF84DF30 start looping - EventLoop.cc:109
20170831 13:05:23.247016Z 21969 TRACE poll fd total count 3 - EPollPoller.cc:59
20170831 13:05:33.316504Z 21969 TRACE poll nothing happended - EPollPoller.cc:77
20170831 13:05:33.316546Z 21969 TRACE doPendingFunctors EventLoop doPendingFunctors 0xBF84DF30 - EventLoop.cc:305
20170831 13:05:33.316558Z 21969 TRACE poll fd total count 3 - EPollPoller.cc:59
20170831 13:05:43.327125Z 21969 TRACE poll nothing happended - EPollPoller.cc:77
20170831 13:05:43.327176Z 21969 TRACE doPendingFunctors EventLoop doPendingFunctors 0xBF84DF30 - EventLoop.cc:305

20170831 13:05:43.327190Z 21969 TRACE poll fd total count 3 - EPollPoller.cc:59

以上为上一节的初始化

20170831 13:05:50.571772Z 21969 TRACE poll 1 events happended - EPollPoller.cc:68
20170831 13:05:50.571866Z 21969 TRACE printActiveChannels {6: IN }  - EventLoop.cc:326

20170831 13:05:50.571879Z 21969 TRACE handleEventWithGuard 6: IN  - Channel.cc:88

使用nc命令有一个连接接入

20170831 13:05:50.584189Z 21969 INFO  TcpServer::newConnection [EchoServer] - new connection [EchoServer-0.0.0.0:2000#1] from 127.0.0.1:60898 - TcpServer.cc:84
20170831 13:05:50.597479Z 21969 TRACE Channel fd_ = 8 - Channel.cc:35
20170831 13:05:50.597526Z 21969 TRACE Channel loop_ = 0xBF84DF30 - Channel.cc:36

20170831 13:05:50.597754Z 21969 DEBUG TcpConnection TcpConnection::ctor[EchoServer-0.0.0.0:2000#1] at 0x9A1C518 fd=8 - TcpConnection.cc:63

new Channel  TcpConnection

20170831 13:05:50.597791Z 21969 TRACE updateChannel fd = 8 events = 3 index = -1 - EPollPoller.cc:113

20170831 13:05:50.597831Z 21969 TRACE update epoll_ctl op = ADD fd = 8 event = { 8: IN PRI  } - EPollPoller.cc:181

enable了Channel

20170831 13:05:50.597852Z 21969 TRACE onConnection 127.0.0.1:60898 -> 127.0.0.1:2000 is UP - EchoServer_unittest.cc:43

20170831 13:05:50.597869Z 21969 INFO  unrecovered=0 rto=201000 ato=0 snd_mss=16384 rcv_mss=536 lost=0 retrans=0 rtt=1000 rttvar=500 sshthresh=2147483647 cwnd=10 total_retrans=0 - EchoServer_unittest.cc:46

20170831 13:05:50.597889Z 21969 TRACE sendInLoop  TcpConnection::sendInLoop  - TcpConnection.cc:147

20170831 13:05:50.598025Z 21969 TRACE sendInLoop  sockets::write 6 - TcpConnection.cc:157

send了 hello 关于

writeable事件的busy loop避免见这里点击打开链接

20170831 13:05:50.598091Z 21969 TRACE doPendingFunctors EventLoop doPendingFunctors 0xBF84DF30 - EventLoop.cc:305
20170831 13:05:50.598109Z 21969 TRACE poll fd total count 4 - EPollPoller.cc:59
20170831 13:06:00.617974Z 21969 TRACE poll nothing happended - EPollPoller.cc:77
20170831 13:06:00.618016Z 21969 TRACE doPendingFunctors EventLoop doPendingFunctors 0xBF84DF30 - EventLoop.cc:305

20170831 13:06:00.618024Z 21969 TRACE poll fd total count 4 - EPollPoller.cc:59

nc命令发了world

20170831 13:06:00.829632Z 21969 TRACE poll 1 events happended - EPollPoller.cc:68
20170831 13:06:00.829677Z 21969 TRACE printActiveChannels {8: IN }  - EventLoop.cc:326
20170831 13:06:00.829687Z 21969 TRACE handleEventWithGuard 8: IN  - Channel.cc:88
20170831 13:06:00.829735Z 21969 TRACE onMessage EchoServer-0.0.0.0:2000#1 recv 6 bytes at 1504184760.829630 is world

 - EchoServer_unittest.cc:54

20170831 13:06:00.829743Z 21969 TRACE sendInLoop  TcpConnection::sendInLoop  - TcpConnection.cc:147

20170831 13:06:00.829769Z 21969 TRACE sendInLoop  sockets::write 6 - TcpConnection.cc:157

原路返回了world

20170831 13:06:00.829776Z 21969 TRACE doPendingFunctors EventLoop doPendingFunctors 0xBF84DF30 - EventLoop.cc:305
20170831 13:06:00.829782Z 21969 TRACE poll fd total count 4 - EPollPoller.cc:59