分类目录归档:programming

final object?

使用final修饰object的场景极少见,需要显式打开-Yoverride-objects编译选项才行:

 ➜  scala -Yoverride-objects
Welcome to Scala version 2.11.6 (Java HotSpot(TM) 64-Bit Server VM, Java 1.8.0_51).
Type in expressions to have them evaluated.
Type :help for more information.

scala> class A { object B }
defined class A

scala> class C extends A  { override object B {}  }
defined class C

如果A内部对object B使用final修饰了,子类C就不能覆盖这个object,不过它的意义是什么?这里object B是一个module,要解释object为何被当作module来设计,需要整理一下,等有时间再说。

PS,我刚发现2.11版本之后repl下,当你定义一个object时,提示已经不同了,在2.11版本之前,repl下会显示 "defined module XXX", 而 2.11 里已经变成了 "defined object XXX",可能隐含着设计者对module(早期scala中module应该是借鉴ML语言的module)这个术语可能存在理解不一致的担心,所以不再使用这个名词(只是我的猜测)。

socketRead0阻塞2个半小时?

前几个月我们遇到过某些http请求会在本机会阻塞2个半小时左右最后成功返回的情况。经过排查发现问题并不在对方服务器,而是这2个半小时基本都是在自己的网络环境阻塞,通过dns端日志发现请求到达dns服务器也是2个半小时后。

在geek talk群里有人指出,glibc的低版本会在查完域名后把拿到的ip反过来查域名,dns服务器都不支持反解就一层层的传给其他dns,可能会变慢。redhat在6u fix了这个问题。但跟我们的情况不符。

当时的堆栈显示阻塞在socket的读取上(我不确定这里的连接是复用上次HttpURLConnection创建过的连接,还是首次跟对方建立连接),我google到有些人也遇到过相似的问题,hang在同样的代码上,疑似是虚拟机(kvm/vmware)或jdk网络层面的bug (JDK 1.8.0_65), 因为无法稳定的重现,没有进一步验证,记录一下这个诡异的问题

at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:335)
- locked <0x0000000c868c460> (a java.io.BufferedInputStream)
at sun.net.www.MeteredStream.read(MeteredStream.java:134)
- locked <0x0000000c868c420> (a sun.net.www.http.KeepAliveStream)
at java.io.FilterInputStream.read(FilterInputStream.java:133)
at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3336)
at java.io.FilterInputStream.read(FilterInputStream.java:133)

《Scala函数式编程》中文版勘误2

感谢 shuai.xie 提出的这段漏掉的内容,这里补充一下。

这里b的类型声明并不是必须的。因为我们已经告诉Scala返回类型为B => C,Scala会从上下文获知b的类型,方法的实现部分只需要写为 b => f(a,b)就可以了。如果Scala能够推断出函数字面量的类型,就可以省略掉它的类型声明。

相关阅读:《Scala函数式编程》中文版勘误

记录几个实践中的问题

1) nginx禁止对写操作timeout时retry

以前遇到的一个case,业务那边说一笔请求从nginx端发送给后端tomcat了2次(落在两个不同的tomcat节点上)。后来发现是nginx发给后端节点timeout,然后做了重试,发给了另一个节点。默认情况下nginx对后端error 和 timeout 都会做retry,可以明确的禁止在timeout的情况下禁止retry。当然如果集群读写分离的话,对于只读集群retry是无所谓的,但对于写确实存在问题。

2) kafka重启时因为数据日志文件名被人重命名过而导致启动失败

启动kafka broker的时候,会重新load之前的每个topic的数据,正常情况下会提示每个topic恢复完成。

INFO Recovering unflushed segment 588022 in log xxx-topic-0. (kafka.log.Log)
INFO Completed load of log xxx-topic-0 with log end offset 590676 (kafka.log.Log)

但当有些topic下的数据恢复失败的时候,会导致broker关闭,异常如下

ERROR There was an error in one of the threads during logs loading: java.lang.NumberFormatException: For input string: "test" (kafka.log.LogManager)
FATAL [Kafka Server 3], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)

java.lang.NumberFormatException: For input string: "test"
      at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
      at java.lang.Long.parseLong(Long.java:589)
      at java.lang.Long.parseLong(Long.java:631)
      at scala.collection.immutable.StringLike$class.toLong(StringLike.scala:251)
      at scala.collection.immutable.StringOps.toLong(StringOps.scala:30)
      at kafka.log.Log$$anonfun$loadSegments$4.apply(Log.scala:152)
      at kafka.log.Log$$anonfun$loadSegments$4.apply(Log.scala:141)
      at scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:778)
      at scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
      at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
      at scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:777)
      at kafka.log.Log.loadSegments(Log.scala:141)
      at kafka.log.Log.<init>(Log.scala:67)
      at kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$3$$anonfun$apply$7$$anonfun$apply$1.apply$mcV$sp(LogManager.scala:142)
      at kafka.utils.Utils$$anon$1.run(Utils.scala:54)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      at java.lang.Thread.run(Thread.java:745)

这是因为某个目录下,存在一个 test.log 的文件

$ ls mytopic-0/
00000000000000000485.index  00000000000000000485.log  00000000000000000568.index  00000000000000000568.log  test.log

看上去这个 test.log 当时是把 00…log 给拷贝了一个,然后用编辑器去查看内容。而事后忘了清理掉,导致重启时把这个文件当成一个畸形文件了。因为kafka broker要求所有数据文件名称都是Long类型的。

3) 又一个actor阻塞的例子

在我自己的mac上测试的时候,一切正常,部署到dev环境就严重超时。jstack观察发现又是误用阻塞操作导致所有actor的线程都被阻塞所致,当时 EventProcessor 这个 Router 背后的实例数设置的是40,而这台dev环境的linux只有2核,根据当时akka的配置里的并发因子算出并发线程数是32,所以32个线程基本都被 eventProcessor 的40个actor全给占用了,因为它是不断发消息轮询的(我的mac是8核,运行时的线程数要大于40不会发生全部被阻塞的情况)。解决方式,一方面调大并发因子,把线城数提升上去,另一方面控制 eventProcessor 的实例数,不让它的阻塞操作影响到其他actor。(其实根上是没设计好,没有隔离阻塞操作,只不过这正好是个小应用,不需要过多考虑。)

OneApm的问题

1) 我们没有使用它的大数据版本,普通版本在压测情况下服务器端如果吞吐不够,agent端会缓存大量的数据导致full gc,这里它占据了1G的内存

2) 对HttpURLConnection拦截时可能发生空指针异常,导致业务线程终止

java.lang.NullPointerException
 at com.blueware.monitor.bridge.reflect.ClassReflection$2.run(ClassReflection.java:30) ~[?:?]
 at com.blueware.monitor.bridge.reflect.ClassReflection$2.run(ClassReflection.java:28) ~[?:?]
 at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_65]
 at com.blueware.monitor.bridge.reflect.ClassReflection.loadClass(ClassReflection.java:28) ~[?:?]
 at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441) ~[?:1.8.0_65]
 at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979) ~[?:1.8.0_65]
 at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489) ~[?:1.8.0_65]
 at com...

tomcat8.5.8遇到的两个问题

压力测试场景,前端nginx反向代理到4个tomcat实例,在其中的一个实例上产生了大量的countDownConnection Incorrect connection count警告

 WARNING [http-nio-8080-exec-48] org.apache.tomcat.util.net.AbstractEndpoint.countDownConnection Incorrect connection count, multiple socket.close called on the same socket.

另外一个异常是4个tomcat实例上都看到的NPE异常:

Exception in thread "http-nio-8080-AsyncTimeout" java.lang.NullPointerException
  at org.apache.coyote.AbstractProcessor.doTimeoutAsync(AbstractProcessor.java:528)
  at org.apache.coyote.AbstractProcessor.timeoutAsync(AbstractProcessor.java:518)
  at org.apache.coyote.AbstractProtocol$AsyncTimeout.run(AbstractProtocol.java:1130)
  at java.lang.Thread.run(Thread.java:745)

使用了servlet3.0,connector配置如下:

 <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
           connectionTimeout="20000" redirectPort="8443" maxParameterCount="2000" maxKeepAliveRequests="-1"
       maxThreads="200" maxPostSize="20971520" acceptCount="1024" useBodyEncodingForURI="true"
        URIEncoding="UTF-8"/>

已将bug提交到了bugzilla,在这里记录一下,后续跟踪。

scala雾中风景(27): lambda表达式里的return是抛异常实现的

尽管Scala和其他函数式编程都不太鼓励使用return,但我不喜欢太多缩进的代码,所以很少用较多的逻辑嵌套(除非是那种非常对称的嵌套),而是喜欢将不满足条件的先return掉。最近遇到一个scala里的流控陷阱,即在lambda里的return背后实际是通过特定的异常来实现的。

对于流控和异常捕获之前也遇到过其他陷阱,但稍不留意仍可能重犯,比如下面这段代码:

try {
    ...
    for (topicMeta <- resp.topicsMetadata; partMeta <- topicMeta.partitionsMetadata) {
      if (topicMeta.topic == p.topic && partMeta.partitionId == p.partition) {
        redisClient.hset(key, field, node.host + ":" + node.port)
        return
      }
    }
} catch {
    case e: Throwable =>
    ...
}

它是一段在actor里的逻辑,因为不希望非预期异常导致这个actor重启,所以是对Throwable进行的捕获,然而运行时竟捕获到了scala.runtime.NonLocalReturnControl$mcV$sp这样的异常。for语法糖容易让人忘记它里面的操作可能是一段匿名函数,简化一下这个例子:

➜  cat Test.scala
object Test {
    def main(args: Array[String]) {
        val list = List("A", "B", "C")
        for (e1 <- list) {
            if (e1 == "C") {
                println("ok, do something.")
                return
            }
        }
    }   
}

看看它编译的中间环节:

➜  scalac -Xprint:explicitouter Test.scala
[[syntax trees at end of             explicitouter]] // Test.scala
package <empty> {
object Test extends Object {
def <init>(): Test.type = {
  Test.super.<init>();
  ()
};
def main(args: Array[String]): Unit = {
  <synthetic> val nonLocalReturnKey1: Object = new Object();
  try {
    val list: List[String] = immutable.this.List.apply[String](scala.this.Predef.wrapRefArray[String](Array[String]{"A", "B", "C"}));
    list.foreach[Unit]({
      @SerialVersionUID(value = 0) final <synthetic> class $anonfun extends scala.runtime.AbstractFunction1[String,Unit] with Serializable {
        def <init>(): <$anon: String => Unit> = {
          $anonfun.super.<init>();
          ()
        };
        final def apply(e1: String): Unit = if (e1.==("C"))
          {
            scala.this.Predef.println("ok, do something.");
            throw new scala.runtime.NonLocalReturnControl$mcV$sp(nonLocalReturnKey1, ())
          }
        else
          ()
      };
      (new <$anon: String => Unit>(): String => Unit)
    })
  } catch {
    case (ex @ (_: scala.runtime.NonLocalReturnControl[Unit @unchecked])) => if (ex.key().eq(nonLocalReturnKey1))
      ex.value$mcV$sp()
    else
      throw ex
  }
}
}
}

很明显return在嵌套的匿名函数里是无法跳出外层函数的,所以编译器通过抛出 scala.runtime.NonLocalReturnControl 异常来实现跳出最外层。所有的lambda中使用return都是如此:

def main(args: Array[String]) {
    val lambda: String => Unit =
        (str: String) => { if ("hit" == str) return } //跳出main

    try {
        lambda("hit")
    } catch {
        case e: Throwable => //scala.runtime.NonLocalReturnControl
        e.printStackTrace()
    }
}

还是要注意对Throwable的捕获,不要干扰流控逻辑:

try{
    ...
}catch {
case e0: ControlThrowable => throw e0 // 不要干预流控的异常
case e1: Throwable => e1.printStackTrace
}   

JDK在mac和linux上对connection reset的行为不一致?

遇到一个JDK(版本都是1.8.0_51-b16)在mac和linux上行为不一致的问题,这个问题是针对redis服务器端关闭连接时的状况处理;即在redis-server端设置连接的空闲时间,当超过这个空闲时间后server主动把该连接关闭掉。在我的mac上这个行为是符合预期的,对这个超时的连接再发起请求时会抛出 SocketException "Connection Reset",但在linux上却不会。

简单模拟一下,在Redis服务端配置timeout为3秒,客户端建立连接之后 sleep 4秒(或更久),让连接超时

import java.io.InputStream;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.net.Socket;

public class ConnRestTest {

    public static void main(String[] args) throws Exception {
        Socket socket = new Socket();
        socket.connect(new InetSocketAddress("localhost", 6379));

        InputStream is = socket.getInputStream();
        OutputStream os = socket.getOutputStream();

        Thread.sleep(4000);

        os.write("*1\r\n$4\r\nPING\r\n".getBytes());
        os.flush();

        for (int i = 0; i < 7; i++) {
            int r = is.read();
            System.out.print( r == -1 ? r : (char) r);
        }

        socket.close();
    }
}

上面的代码在mac上运行后会看到如下异常(如果注释掉 Thread.sleep(4000) 会得到 "+PONG\r\n")

Exception in thread "main" java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(SocketInputStream.java:209)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.net.SocketInputStream.read(SocketInputStream.java:223)
    at com.wacai.common.redis.io.Test.main(Test.java:23)    

而在linux上运行后则是打印7个连续的"-1",即并不会抛出"Connection reset"

分别进行tcpdump,在mac上:

 ➜  sudo tcpdump -i lo0 port 6379

23:13:43.398003 IP localhost.63864 > localhost.6379: Flags [S], seq 1658673677, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 1063188198 ecr 0,sackOK,eol], length 0
23:13:43.398064 IP localhost.6379 > localhost.63864: Flags [S.], seq 355134851, ack 1658673678, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 1063188198 ecr 1063188198,sackOK,eol], length 0
23:13:43.398075 IP localhost.63864 > localhost.6379: Flags [.], ack 1, win 12759, options [nop,nop,TS val 1063188198 ecr 1063188198], length 0
23:13:43.398085 IP localhost.6379 > localhost.63864: Flags [.], ack 1, win 12759, options [nop,nop,TS val 1063188198 ecr 1063188198], length 0

23:13:47.063640 IP localhost.6379 > localhost.63864: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 1063191852 ecr 1063188198], length 0
23:13:47.063671 IP localhost.63864 > localhost.6379: Flags [.], ack 2, win 12759, options [nop,nop,TS val 1063191852 ecr 1063191852], length 0

23:13:48.403144 IP localhost.63864 > localhost.6379: Flags [P.], seq 1:15, ack 2, win 12759, options [nop,nop,TS val 1063193184 ecr 1063191852], length 14
23:13:48.403255 IP localhost.6379 > localhost.63864: Flags [R], seq 355134853, win 0, length 0  

在linux上:

$ sudo tcpflow -p -c -i lo port 6379

00:26:13.303233 IP localhost.34609 > localhost.6379: Flags [S], seq 1094106697, win 43690, options [mss 65495,sackOK,TS val 8462190 ecr 0,nop,wscale 7], length 0
00:26:13.303272 IP localhost.6379 > localhost.34609: Flags [S.], seq 2755621045, ack 1094106698, win 43690, options [mss 65495,sackOK,TS val 8462190 ecr 8462190,nop,wscale 7], length 0
00:26:13.303298 IP localhost.34609 > localhost.6379: Flags [.], ack 1, win 342, options [nop,nop,TS val 8462190 ecr 8462190], length 0

00:26:17.037992 IP localhost.6379 > localhost.34609: Flags [F.], seq 1, ack 1, win 342, options [nop,nop,TS val 8465925 ecr 8462190], length 0
00:26:17.038450 IP localhost.34609 > localhost.6379: Flags [.], ack 2, win 342, options [nop,nop,TS val 8465926 ecr 8465925], length 0

00:26:18.305591 IP localhost.34609 > localhost.6379: Flags [P.], seq 1:15, ack 2, win 342, options [nop,nop,TS val 8467193 ecr 8465925], length 14
00:26:18.305630 IP localhost.6379 > localhost.34609: Flags [R], seq 2755621047, win 0, length 0     

在mac上比linux上多了一次在连接建立后从server发给client端的ack,在3秒之后,连接因为超过空闲时间server端向client端发起了fin,client回复ack,之后client端程序对socket进行写操作,在tcpdump里看到标记为P的标记,然后server端发送了reset

在linux上看到连接状态的变化也符合预期:

$ netstat -antp | grep 6379
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.1:6379          0.0.0.0:*               LISTEN      -
tcp        0      0 127.0.0.1:6379          127.0.0.1:34607         ESTABLISHED -
tcp6       0      0 127.0.0.1:34607         127.0.0.1:6379          ESTABLISHED 3683/java

tcp        0      0 127.0.0.1:6379          0.0.0.0:*               LISTEN      -
tcp        0      0 127.0.0.1:6379          127.0.0.1:34607         FIN_WAIT2   -
tcp6       1      0 127.0.0.1:34607         127.0.0.1:6379          CLOSE_WAIT  3683/java

按说server端发送reset标记后,mac上抛出异常的行为更符合预期,可能是JDK网络层面的实现细节不同,或者tcpdump出的数据已经能解释原因只是我看不出来。

zsh的字符串替换引起的卡顿

我的mac系统每次启动后第一次打开iterm2的时候,oh-my-zsh的启动总是明显的卡顿一下,而之后退出iterm2重启动则不会有这个卡顿,也就是只在第一次启动iterm2的时候发生。对启动的zsh增加了-xv参数后观察,发现这个卡顿发生在git_compare_version函数的第4行:

找到这个函数后,发现第4行的操作并不是git等网络操作,而是一个字符串替换的操作,它使用zsh内置的字符串替换功能:INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]})

非常的不符合直觉(直觉上以为卡顿是因为网络阻塞引起的),模拟一下,在一个脚本里使用这个字符串替换操作,看看具体的耗时情况:

$ cat zsh-test.sh
#!/usr/bin/env zsh -xv
export PS4=$'%D{%M%S%.} %N:%i> '

INSTALLED_GIT_VERSION=($(command git --version 2>/dev/null));
INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]});
echo "$INSTALLED_GIT_VERSION"

然后再启动时调用这个zsh脚本:

$ cat run.sh
#!/usr/bin/env zsh -xv
export PS4=$'%D{%M%S%.} %N:%i> '
./zsh-test.sh

重启系统,启动后在bash下执行run.sh脚本:

INSTALLED_GIT_VERSION=($(command git --version 2>/dev/null));
5649865 ./zsh-test.sh:4> INSTALLED_GIT_VERSION=5649867 ./zsh-test.sh:4> git --version
5649865 ./zsh-test.sh:4> INSTALLED_GIT_VERSION=( git version 2.8.4 '(Apple' 'Git-73)' ) 
INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]});
5650999 ./zsh-test.sh:5> INSTALLED_GIT_VERSION=( 2 8 4 )

看到zsh-test.sh里的第5行字符串替换的操作耗时用了1秒多时间,如果再次执行的话会降到几个毫秒。这真是个蹊跷的问题,发邮件给 zsh-works@zsh.org 好几周也没有人回复,先在博客里记录一下这个问题,以后再追踪。zsh版本是:5.2 (x86_64-apple-darwin16.0.0)。