• 카테고리

    질문 & 답변
  • 세부 분야

    백엔드

  • 해결 여부

    미해결

특정 repository를 이용해 save 후 DB에도 반영된 정보가 해당 repository 를 통해 find 시 DB반영된 정보를 가지고 오지 못하는 현상에 대한 질문드립니다.

20.09.11 18:17 작성 조회수 237

0

아래와 같은 소스들이 있습니다.

1. 인터페이스기반의 repository

public interface TestModelRepository extends JpaRepository<TestModel, Long>{

}

2. 서비스

@Service
public class TestService {
    ...
    @Autowired
    TestModelRepository testModelRepository;
    public void test() {
        ...
        while(true) {
            Optional<TestModel> optTestModel = testModelRepository.findById(id);
            TestModel testModel;
            if(optTestModel.isPresent()) {
                testModel = optTestModel.get();
                logger.info("testModel: {}", testModel.toString());
            }
        }
    }
    ...
}

3. worker thread를 통해 호출되는 코드

public class TestAction {
    ...
    public void act(TestModelRepository testModelRepository, TestModel testModel) {
        ...
        testModel.setComment("new comment");
        TestModel savedTestModel = testModelRepository.save(testModel);
        logger.info("savedTestModel: {}", savedTestModel.toString());
    }
    ...
}

상태

  1. TestService의 test()에 의해 다른 worker thread에서 동작하는 TestAction의 act()가 호출됩니다.
    1. TestAction.act에 전달된 testModelRepository는 TestService의 것과 동일한 레퍼런스입니다.
  2. TestAction.act()에 의해 정상적으로 DB에 저장된 것이 확인됩니다.
  3. 그런데, TestService의 test()에서 주기적으로 TestAction.act()호출 시에 전달한 testModel에 대한 id를 이용해서 `testModelRepository.findById(id)` 를 수행하면 저장된 값이 아닌 저장 이전의 값만 가지고 오고 있습니다.

질문(이해가되지 않는 부분)

위 상태 1.에 의해 저장에 의해 SimpleJpaRepository의 save()의 처리를 타면서 저장한 정보가 merge되었기 때문에 Persistence Context에 정상적으로 적용이 될 것이기 때문에 상태 3의 `testModelRepository.findById(id)` 코드를 통해 해당 entity를 가져오면 정상적으로 변경된 내용을 가지고 와야 할 것 같은데 이해가 되지 않습니다.(제가 Persistence Context관련하여 놓치고 있는 부분이 있는 것 같은데 잘 모르겠네요.)

왜 그럴까요?

답변 6

·

답변을 작성해보세요.

1

네 로그에 쓰레드 이름도 출력이 되고 SQL로 찍히고 있으니까 잘 살펴보시면서 조정해 보세요.

1

첫 번째 경우 로그를 보면 update가 나중에 발생하고 그 이후에 select가 발생하질 않네요. 그리고 insert가 task-3이라는 쓰레드에서 실행되고 나머지 select와 update는 같은 쓰레드 thread-20에서 실행이 되는데 그게 원하던 실행 방식인지 잘 모르겠습니다.

반면에 두번째 경우의 로그를 보면 select는 thread-19에서 계속 하고 있고 update는 thread-20에서 발생하고 있고 update 이후에도 계속 select를 해서 바뀐 값을 가져온걸로 보이네요.

말씀하신대로 비동기를 쓰는 방법이 뭔가 잘못된거 같습니다. 코드를 열어보았으나 @EnableAync나 @Async 같은걸 사용한 곳이 보이지 않고 Thread를 사용한 코드가 보이는데 제가 개인 프로젝트까지 봐드릴 여유가 없어 죄송합니다.

1

글쎄요. 보내주신 코드만으로는 잘 모르겠네요. 대충 원하시는 상황을 만들어 봤는데 제 경우에는 예상한대로 동작하는 거 같습니다. 

@Service
public class BookService {

@Autowired
BookRepository bookRepository;

public void test() {
Book spring = bookRepository.findByTitle("spring");

new Thread(() -> {
try {
Thread.sleep(2000L);
} catch (InterruptedException e) {
e.printStackTrace();
}
spring.setTitle("keesun");
bookRepository.save(spring);
}).start();


while (true) {
Optional<Book> byId = bookRepository.findById(spring.getId());
byId.ifPresent(b -> System.out.println(b.getTitle()));

try {
Thread.sleep(2000L);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}

@PostConstruct
public void init() {
Book spring = bookRepository.findByTitle("spring");
if (spring == null) {
Book book = new Book();
book.setTitle("spring");
bookRepository.save(book);
}
}

}

Hibernate: select book0_.id as id1_0_, book0_.isbn as isbn2_0_, book0_.title as title3_0_ from book book0_ where book0_.title=?

spring

Hibernate: select book0_.id as id1_0_0_, book0_.isbn as isbn2_0_0_, book0_.title as title3_0_0_ from book book0_ where book0_.id=?

Hibernate: update book set isbn=?, title=? where id=?

keesun

keesun

처음엔 원래 저장되어 있던 spring이라는 값이 출력되고 그 이후에는 쓰레드에서 업데이트 한 값으로 출력되는걸 확인할 수 있었습니다. 그런데 처음에 쓰레드가 더 빨리 실행이되면 그 이후에는 계속 keesun 밖에 안보이기 때문에 처음에 sleep을 사용해서 조금 딜레이를 줘서 spring이라는 값이 보이게 했구요.

위에 제가 작성한 코드랑 차이나는게 있는지 확인해 보시고 전체 코드를 공유해 주시면 좋겠습니다.

0

답변 감사합니다.

스스로 더 파악해보고, 문제 해결되면 공유하겠습니다.

0

간단한 샘플을 만들어서 재현이 되는 것을 확인했고, 아래 링크에 재현 되는 소스를 공유했습니다.

https://gitlab.com/xoska74/jpademo

앞서 말씀드린것 처럼 controller파트에서 아래와 같이(thread를 생성하지 않고)  호출하면

@RequestMapping(value = "/test", method = RequestMethod.GET)
public Callable<Boolean> test() {
        return () -> {
        testService.test();
        return true;
    };
}

출력되는 로그는 아래와 같고,(comment를 completed로 업데이트해서 find시에 completed가 나타날 것을 예상했으나, 변경되지 않고 comment에 no comment가 나타남)

2020-09-12 11:52:55,443 DEBUG [task-3                ] o.hibernate.SQL          : 
    /* insert com.tnkim.jpademo.model.test.TestModel
        */ insert 
        into
            test_model
            (comment, name, id) 
        values
            (?, ?, ?)
Hibernate: 
    /* insert com.tnkim.jpademo.model.test.TestModel
        */ insert 
        into
            test_model
            (comment, name, id) 
        values
            (?, ?, ?)
2020-09-12 11:52:55,447 TRACE [task-3                ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [VARCHAR] - [no comment]
2020-09-12 11:52:55,448 TRACE [task-3                ] o.h.t.d.s.BasicBinder    : binding parameter [2] as [VARCHAR] - [mac]
2020-09-12 11:52:55,449 TRACE [task-3                ] o.h.t.d.s.BasicBinder    : binding parameter [3] as [BIGINT] - [8]
2020-09-12 11:52:55,461 INFO  [task-3                ] c.t.j.s.TestService      : saved model: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:52:55,482 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:52:55,482 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:52:55,483 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [8]
2020-09-12 11:52:55,493 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [no comment]
2020-09-12 11:52:55,494 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:52:55,508 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    /* load com.tnkim.jpademo.model.test.TestModel */ select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    /* load com.tnkim.jpademo.model.test.TestModel */ select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:52:55,509 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [8]
2020-09-12 11:52:55,511 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [no comment]
2020-09-12 11:52:55,512 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:52:55,514 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    /* update
        com.tnkim.jpademo.model.test.TestModel */ update
            test_model 
        set
            comment=?,
            name=? 
        where
            id=?
Hibernate: 
    /* update
        com.tnkim.jpademo.model.test.TestModel */ update
            test_model 
        set
            comment=?,
            name=? 
        where
            id=?
2020-09-12 11:52:55,514 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [VARCHAR] - [completed]
2020-09-12 11:52:55,515 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [2] as [VARCHAR] - [mac]
2020-09-12 11:52:55,515 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [3] as [BIGINT] - [8]
2020-09-12 11:52:56,491 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:52:57,495 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:52:58,498 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:52:59,505 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:53:00,510 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)
2020-09-12 11:53:01,514 INFO  [task-3                ] c.t.j.s.TestService      : found TestModel: TestModel(id=8, name=mac, comment=no comment)

controller파트에서 thread를 생성하여 service의 test()를  호출하면

    @RequestMapping(value = "/test", method = RequestMethod.GET)
    public Callable<Boolean> test() {
        return () -> {
            new Thread(() -> {
                try {
                    testService.test();
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }).start();

            return true;
        };
    }

출력되는 로그는 아래와 같이 정상적으로 처리되어 출력됩니다.(comment를 completed로 업데이트해서 find시에 completed가 정상적으로 나타남)

2020-09-12 11:56:18,744 DEBUG [Thread-19             ] o.hibernate.SQL          : 
    /* insert com.tnkim.jpademo.model.test.TestModel
        */ insert 
        into
            test_model
            (comment, name, id) 
        values
            (?, ?, ?)
Hibernate: 
    /* insert com.tnkim.jpademo.model.test.TestModel
        */ insert 
        into
            test_model
            (comment, name, id) 
        values
            (?, ?, ?)
2020-09-12 11:56:18,750 TRACE [Thread-19             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [VARCHAR] - [no comment]
2020-09-12 11:56:18,750 TRACE [Thread-19             ] o.h.t.d.s.BasicBinder    : binding parameter [2] as [VARCHAR] - [mac]
2020-09-12 11:56:18,751 TRACE [Thread-19             ] o.h.t.d.s.BasicBinder    : binding parameter [3] as [BIGINT] - [9]
2020-09-12 11:56:18,764 INFO  [Thread-19             ] c.t.j.s.TestService      : saved model: TestModel(id=9, name=mac, comment=no comment)
2020-09-12 11:56:18,789 DEBUG [Thread-19             ] o.hibernate.SQL          : 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:56:18,789 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:56:18,791 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [9]
2020-09-12 11:56:18,791 TRACE [Thread-19             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [9]
2020-09-12 11:56:18,804 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [no comment]
2020-09-12 11:56:18,804 TRACE [Thread-19             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [no comment]
2020-09-12 11:56:18,804 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:56:18,804 TRACE [Thread-19             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:56:18,813 INFO  [Thread-19             ] c.t.j.s.TestService      : found TestModel: TestModel(id=9, name=mac, comment=no comment)
2020-09-12 11:56:18,821 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    /* load com.tnkim.jpademo.model.test.TestModel */ select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    /* load com.tnkim.jpademo.model.test.TestModel */ select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:56:18,822 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [9]
2020-09-12 11:56:18,827 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [no comment]
2020-09-12 11:56:18,828 TRACE [Thread-20             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:56:18,829 DEBUG [Thread-20             ] o.hibernate.SQL          : 
    /* update
        com.tnkim.jpademo.model.test.TestModel */ update
            test_model 
        set
            comment=?,
            name=? 
        where
            id=?
Hibernate: 
    /* update
        com.tnkim.jpademo.model.test.TestModel */ update
            test_model 
        set
            comment=?,
            name=? 
        where
            id=?
2020-09-12 11:56:18,830 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [VARCHAR] - [completed]
2020-09-12 11:56:18,830 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [2] as [VARCHAR] - [mac]
2020-09-12 11:56:18,831 TRACE [Thread-20             ] o.h.t.d.s.BasicBinder    : binding parameter [3] as [BIGINT] - [9]
2020-09-12 11:56:19,818 DEBUG [Thread-19             ] o.hibernate.SQL          : 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
Hibernate: 
    select
        testmodel0_.id as id1_0_0_,
        testmodel0_.comment as comment2_0_0_,
        testmodel0_.name as name3_0_0_ 
    from
        test_model testmodel0_ 
    where
        testmodel0_.id=?
2020-09-12 11:56:19,818 TRACE [Thread-19             ] o.h.t.d.s.BasicBinder    : binding parameter [1] as [BIGINT] - [9]
2020-09-12 11:56:19,820 TRACE [Thread-19             ] o.h.t.d.s.BasicExtractor : extracted value ([comment2_0_0_] : [VARCHAR]) - [completed]
2020-09-12 11:56:19,821 TRACE [Thread-19             ] o.h.t.d.s.BasicExtractor : extracted value ([name3_0_0_] : [VARCHAR]) - [mac]
2020-09-12 11:56:19,824 INFO  [Thread-19             ] c.t.j.s.TestService      : found TestModel: TestModel(id=9, name=mac, comment=completed)
2020-09-12 11:56:19,824 INFO  [Thread-19             ] c.t.j.s.TestService      : the comment of the testModel : completed

0

선생님, 답변감사합니다~ ^ㅡ^

현재 아래와 같은 configuration을 설정한 상태에서 HTTP API를 통해 말씀드렸던 처리를 하려고 하는 상황입니다.

@Configuration
@EnableAsync
public class AsyncMVCConfig implements WebMvcConfigurer {

    @Bean
    @RequestScope
    public UserData requestScopeUserData() {
        return new UserData();
    }

    @Bean
    public AuthInterceptor interceptor() {
        return new AuthInterceptor();
    }

    @Bean
    public AsyncTaskExecutor asyncTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(100);
        executor.setMaxPoolSize(1000);
        executor.setQueueCapacity(1000);
        executor.setThreadNamePrefix("task-");
        executor.initialize();
        return executor;
    }

    @Override
    public void configureAsyncSupport(AsyncSupportConfigurer configurer) {
        configurer.setTaskExecutor(asyncTaskExecutor());
    }
}

기존의 서비스를 호출하는 코드는 아래와 같이 AsynTask를 통해 동작하는 controller의 test()가 testService.test()를 호출하는 방식이었고, 말씀드렸던 것처럼 service의 while문 내에서 testModelRepository.findById(id)를 통해 변경된 DB의 data를 가지고 오지 못였습니다.(findById로 가지고 온 최초의 값이 계속 전달되었습니다. 최초 가져온 data를 cache후 계속 변경된 DB내용 이 적용되지 않은채로 cache의 내용을 전달하는 느낌입니다. )

@Autowired
TestService testService;

@AnonymousCallable
@RequestMapping(value = "/test", method = RequestMethod.POST)
public Callable<ResponseObject> test(@ApiParam(required = true, value = "id: 테스트 정보(필수 값)") @RequestBody String jsonString) {
    return () -> {
        JSONObject jsonResult = testService.test(JsonUtils.getMap(jsonString));
        ResponseObject responseObject = new ResponseObject();
        responseObject.putResult(jsonResult);
        return responseObject;
    };
}

그런데, 선생님 테스트 하셨던 것 처럼 new Thread()를 통해 testService.test()를 호출하는 방식을 취하니 정상적으로 service의 while문 내에서 testModelRepository.findById(id)를 통해 변경된 DB의 data를 가지고 오네요.

@AnonymousCallable
@RequestMapping(value = "/test", method = RequestMethod.POST)
public Callable<ResponseObject> test(@ApiParam(required = true, value = "id: 테스트 정보(필수 값)") @RequestBody String jsonString) {
    return () -> {
        new Thread(() -> {
            JSONObject jsonResult = testService.test(JsonUtils.getMap(jsonString));
        }).start();
        JSONObject jsonResult = new JSONObject();
        ResponseObject responseObject = new ResponseObject();
        responseObject.putResult(jsonResult);
        return responseObject;
    };
}

AsyncTask에서 처리하는 것과 Thread에서 처리하는 것의 차이가 있는것 같은데 잘 이해가 되지 않네요.

글로 먼저 써서 올립니다.

재현될 수 있는 예제를 하나 만들어서 다시 질문드리도록 하겠습니다.

감사합니다.