spring-boot で非同期処理を試してみた

spring-boot を使ったシンプルな非同期処理

springframeworkは、http://spring.io/projects に紹介されるとおり多くのプロダクトを提供している。そんな私もかなり昔から使っている. 今日そんな spring プロダクトの1つで spring-boot を試してみた.

spring-boot は、springframework を利用したWebアプリケーションを簡単に作成できるようにした product. 特にここ最近は Playframework などJVMのWebフレームワークは注目を集めている気がするけど、spring-bootは、Dropwizard に影響を受けたと言われている.

• 本家 : http://projects.spring.io/spring-boot/
• https://github.com/spring-projects/spring-boot

今回は spring-boot を使って非同期処理を試してみた. まずは、spring-boot は gradle を使った build を推奨しているようだけど、maven も guide にあるし慣れているから maven で作成. ちなみに、IDEは、spring が提供している STS を使った.

• STS で project 作成

• とりあえずこんな感じで project を作成すると pom.xml は以下のように生成された

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.horiga.study</groupId>
    <artifactId>study-simple-springboot</artifactId>
    <version>0.0.1-SNAPSHOT</version>

    <name>study-simple-springboot</name>
    <description>Demo project</description>

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>1.0.2.RELEASE</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <start-class>org.horiga.study.springboot.web.Application</start-class>
        <java.version>1.7</java.version>
    </properties>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

この時点で、既に起動する状態.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.0.2.RELEASE)

2014-05-11 17:08:51.259  INFO 4687 --- [           main] o.h.study.springboot.web.Application     : Starting Application on hiroyuki-no-MacBook-Air.local with PID 4687 (/Users/horiga/Documents/workspace-sts-3.5.0.RELEASE/study-simple-springboot/target/classes started by horiga in /Users/horiga/Documents/workspace-sts-3.5.0.RELEASE/study-simple-springboot)
2014-05-11 17:08:51.315  INFO 4687 --- [           main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@5dcf031e: startup date [Sun May 11 17:08:51 JST 2014]; root of context hierarchy
2014-05-11 17:08:52.420  INFO 4687 --- [           main] .t.TomcatEmbeddedServletContainerFactory : Server initialized with port: 8080
2014-05-11 17:08:52.663  INFO 4687 --- [           main] o.apache.catalina.core.StandardService   : Starting service Tomcat
2014-05-11 17:08:52.664  INFO 4687 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet Engine: Apache Tomcat/7.0.52
2014-05-11 17:08:52.777  INFO 4687 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2014-05-11 17:08:52.778  INFO 4687 --- [ost-startStop-1] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1468 ms
2014-05-11 17:08:53.326  INFO 4687 --- [ost-startStop-1] o.s.b.c.e.ServletRegistrationBean        : Mapping servlet: 'dispatcherServlet' to [/]
2014-05-11 17:08:53.329  INFO 4687 --- [ost-startStop-1] o.s.b.c.embedded.FilterRegistrationBean  : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2014-05-11 17:08:53.632  INFO 4687 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2014-05-11 17:08:53.752  INFO 4687 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2014-05-11 17:08:53.752  INFO 4687 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2014-05-11 17:08:53.938  INFO 4687 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2014-05-11 17:08:53.965  INFO 4687 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080/http
2014-05-11 17:08:53.967  INFO 4687 --- [           main] o.h.study.springboot.web.Application     : Started Application in 3.049 seconds (JVM running for 3.513)

ちなみにここまで1分くらい. 組み込みtomcatが含まれているからそのまま動く. ちなみにデフォルトログはコンソールに出力されて、INFO レベルだから、ログレベルを変更する場合は、--debugを引数につけるとログレベルがDEBUGになった.

では、Controller/RequestMapping, Serviceを追加してみる. そして、非同期を支援するためには、@EnableAsync アノテーションを付与しなければならない

• Application.java

@Configuration
@ComponentScan
@EnableAutoConfiguration
@EnableAsync // support asynchronous methods 
public class Application {

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }
}

• Controller クラス

@Controller
@RequestMapping("/study")
public class StudyController {
    
    private static Logger _log = LoggerFactory.getLogger(StudyController.class);
    
    @Autowired
    private  StudyService studyService;
    
    @RequestMapping("/async/{jobs}")
    @ResponseBody
    String async(@PathVariable("jobs") int jobs) throws Exception {
        
        _log.info(">>> [start] handleRequest !!");
        final long stat = System.currentTimeMillis();
        
        if (jobs <= 0)
            return "done.";
        
        final CountDownLatch latch = new CountDownLatch(jobs);
        List<Future<String>> results = new ArrayList<Future<String>>(jobs);
        for (int i=0; i<jobs; i++) {
            Future<String> res = studyService.processWithAsync(latch, i * 100L);
            results.add(res);
        }
        
        latch.await(1000, TimeUnit.MILLISECONDS);
        
        _log.info(">>> [end] Complete jobs !!: elapsed: {}ms", System.currentTimeMillis() - stat);
        
        StringBuilder sb = new StringBuilder();
        for (Future<String> f : results) {
            sb.append("[");
            if (f.isDone()) {
                sb.append(f.get());
            }
            else {
                sb.append("timeout...");
            }
            sb.append("],");
        }
        
        return sb.toString();
    }
    
    @ResponseStatus(value=HttpStatus.REQUEST_TIMEOUT)
    @ExceptionHandler(value = TimeoutException.class)
    @ResponseBody String handleTimeout() {
        return "timeout";
    }
    
    @ResponseStatus(value=HttpStatus.INTERNAL_SERVER_ERROR)
    @ExceptionHandler(value=Exception.class)
    @ResponseBody String handleException(HttpServletRequest req, Exception exception) {
        return "internal error";
    }
    
}

• Service クラス 非同期対応のメソッドに@Asyncアノテーションを付けて、お決まりのjava.util.concurrent.Future を使う.

@Service
public class StudyService {
    
    private static Logger _log = LoggerFactory.getLogger(StudyService.class);
    
    @Async
    public Future<String> processWithAsync(final CountDownLatch latch, final Long waitMillis) {
        
        try {
            _log.info("[start] processWithAsync(wait={}ms)!!", waitMillis);
            try {
                Thread.sleep(waitMillis);
            } catch (InterruptedException e) {}
            _log.info("[ end ] processWithAsync(wait={}ms)!!", waitMillis);
            return new AsyncResult<String>(
                    new StringBuilder("ID-").append(Thread.currentThread().getName())
                    .append(Thread.currentThread().getId()).toString());
        } finally {
            latch.countDown();
        }
    }
    
}

• ここまで、できたら起動してアクセスしてみる

$ curl localhost:8080/study/async/5 -iks
HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Content-Type: text/plain;charset=ISO-8859-1
Content-Length: 166
Date: Sun, 11 May 2014 08:47:49 GMT

[ID-SimpleAsyncTaskExecutor-641],[ID-SimpleAsyncTaskExecutor-742],[ID-SimpleAsyncTaskExecutor-843],[ID-SimpleAsyncTaskExecutor-944],[ID-SimpleAsyncTaskExecutor-1045],

• ログを見ると非同期になってそう

2014-05-11 17:47:49.248  INFO 4751 --- [nio-8080-exec-1] o.h.s.s.web.controller.StudyController   : >>> [start] handleRequest !!
2014-05-11 17:47:49.248  INFO 4751 --- [cTaskExecutor-6] o.h.s.s.web.service.StudyService         : [start] processWithAsync(wait=0ms)!!
2014-05-11 17:47:49.249  INFO 4751 --- [cTaskExecutor-7] o.h.s.s.web.service.StudyService         : [start] processWithAsync(wait=100ms)!!
2014-05-11 17:47:49.249  INFO 4751 --- [cTaskExecutor-6] o.h.s.s.web.service.StudyService         : [ end ] processWithAsync(wait=0ms)!!
2014-05-11 17:47:49.249  INFO 4751 --- [cTaskExecutor-8] o.h.s.s.web.service.StudyService         : [start] processWithAsync(wait=200ms)!!
2014-05-11 17:47:49.249  INFO 4751 --- [cTaskExecutor-9] o.h.s.s.web.service.StudyService         : [start] processWithAsync(wait=300ms)!!
2014-05-11 17:47:49.249  INFO 4751 --- [TaskExecutor-10] o.h.s.s.web.service.StudyService         : [start] processWithAsync(wait=400ms)!!
2014-05-11 17:47:49.350  INFO 4751 --- [cTaskExecutor-7] o.h.s.s.web.service.StudyService         : [ end ] processWithAsync(wait=100ms)!!
2014-05-11 17:47:49.450  INFO 4751 --- [cTaskExecutor-8] o.h.s.s.web.service.StudyService         : [ end ] processWithAsync(wait=200ms)!!
2014-05-11 17:47:49.550  INFO 4751 --- [cTaskExecutor-9] o.h.s.s.web.service.StudyService         : [ end ] processWithAsync(wait=300ms)!!
2014-05-11 17:47:49.651  INFO 4751 --- [TaskExecutor-10] o.h.s.s.web.service.StudyService         : [ end ] processWithAsync(wait=400ms)!!
2014-05-11 17:47:49.652  INFO 4751 --- [nio-8080-exec-1] o.h.s.s.web.controller.StudyController   : >>> [end] Complete jobs !!: elapsed: 404ms

いやー簡単に実装できた. ほんとここまで30分かからない. Javaはなんだかんだコード量が多くなるとかコンパイルが大変とかあるけど、やっぱりこんな素晴らしいフレームワークとか出てくるし、最近だと大きなところもJVM系(ScalaとかClosure)注目しているみたいだなぁ...

• 作成したproject はこちら