-
카테고리
-
세부 분야
백엔드
-
해결 여부
미해결
특정 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());
}
...
}
상태
- TestService의 test()에 의해 다른 worker thread에서 동작하는 TestAction의 act()가 호출됩니다.
- TestAction.act에 전달된 testModelRepository는 TestService의 것과 동일한 레퍼런스입니다.
- TestAction.act()에 의해 정상적으로 DB에 저장된 것이 확인됩니다.
- 그런데, TestService의 test()에서 주기적으로 TestAction.act()호출 시에 전달한 testModel에 대한 id를 이용해서 `testModelRepository.findById(id)` 를 수행하면 저장된 값이 아닌 저장 이전의 값만 가지고 오고 있습니다.
질문(이해가되지 않는 부분)
위 상태 1.에 의해 저장에 의해 SimpleJpaRepository의 save()의 처리를 타면서 저장한 정보가 merge되었기 때문에 Persistence Context에 정상적으로 적용이 될 것이기 때문에 상태 3의 `testModelRepository.findById(id)` 코드를 통해 해당 entity를 가져오면 정상적으로 변경된 내용을 가지고 와야 할 것 같은데 이해가 되지 않습니다.(제가 Persistence Context관련하여 놓치고 있는 부분이 있는 것 같은데 잘 모르겠네요.)
왜 그럴까요?
답변을 작성해보세요.
1
1
백기선
지식공유자2020.09.12
첫 번째 경우 로그를 보면 update가 나중에 발생하고 그 이후에 select가 발생하질 않네요. 그리고 insert가 task-3이라는 쓰레드에서 실행되고 나머지 select와 update는 같은 쓰레드 thread-20에서 실행이 되는데 그게 원하던 실행 방식인지 잘 모르겠습니다.
반면에 두번째 경우의 로그를 보면 select는 thread-19에서 계속 하고 있고 update는 thread-20에서 발생하고 있고 update 이후에도 계속 select를 해서 바뀐 값을 가져온걸로 보이네요.
말씀하신대로 비동기를 쓰는 방법이 뭔가 잘못된거 같습니다. 코드를 열어보았으나 @EnableAync나 @Async 같은걸 사용한 곳이 보이지 않고 Thread를 사용한 코드가 보이는데 제가 개인 프로젝트까지 봐드릴 여유가 없어 죄송합니다.
1
백기선
지식공유자2020.09.11
글쎄요. 보내주신 코드만으로는 잘 모르겠네요. 대충 원하시는 상황을 만들어 봤는데 제 경우에는 예상한대로 동작하는 거 같습니다.
@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
Tae-Nam Kim
질문자2020.09.12
간단한 샘플을 만들어서 재현이 되는 것을 확인했고, 아래 링크에 재현 되는 소스를 공유했습니다.
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
Tae-Nam Kim
질문자2020.09.12
선생님, 답변감사합니다~ ^ㅡ^
현재 아래와 같은 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에서 처리하는 것의 차이가 있는것 같은데 잘 이해가 되지 않네요.
글로 먼저 써서 올립니다.
재현될 수 있는 예제를 하나 만들어서 다시 질문드리도록 하겠습니다.
감사합니다.
답변 6