Skip to content

Commit

Permalink
Merge pull request #570 from isucon/fix/lock_grade
Browse files Browse the repository at this point in the history 
/gradeを叩く頻度を下げる
  • Loading branch information
@kinmemodoki
kinmemodoki authored Sep 5, 2021
2 parents 58875b6 + eb50009 commit 33bf24c
Show file tree
Hide file tree
Showing 6 changed files with 87 additions and 54 deletions.
13 changes: 8 additions & 5 deletions benchmarker/main.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@ var (
useTLS bool
exitStatusOnFail bool
noLoad bool
noPrepare bool
isDebug bool
showVersion bool
timeoutDuration string
Expand All @@ -68,6 +69,7 @@ func init() {
flag.BoolVar(&exitStatusOnFail, "exit-status", false, "set exit status non-zero when a benchmark result is failing")
flag.BoolVar(&useTLS, "tls", false, "target server is a tls")
flag.BoolVar(&noLoad, "no-load", false, "exit on finished prepare")
flag.BoolVar(&noPrepare, "no-prepare", false, "only load and validation step")
flag.BoolVar(&isDebug, "is-debug", false, "silence debug log")
flag.BoolVar(&showVersion, "version", false, "show version and exit 1")

Expand Down Expand Up @@ -237,10 +239,11 @@ func main() {
panic(err)
}
config := &scenario.Config{
BaseURL: baseURL,
UseTLS: useTLS,
NoLoad: noLoad,
IsDebug: isDebug,
BaseURL: baseURL,
UseTLS: useTLS,
NoLoad: noLoad,
NoPrepare: noPrepare,
IsDebug: isDebug,
}

s, err := scenario.NewScenario(config)
Expand Down Expand Up @@ -290,7 +293,7 @@ func main() {
select {
case <-ticker.C:
scenario.AdminLogger.Printf("[debug] %.f seconds have passed\n", time.Since(startAt).Seconds())
sendResult(s, step.Result(), false, count%5 == 0)
sendResult(s, step.Result(), false, true)
case <-ctx.Done():
ticker.Stop()
return nil
Expand Down
32 changes: 30 additions & 2 deletions benchmarker/model/user.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -22,13 +22,14 @@ type Student struct {
registeredCourses []*Course
announcements []*AnnouncementStatus
announcementIndexByID map[string]int
readAnnouncementCond *sync.Cond
addAnnouncementCond *sync.Cond
readAnnouncementCond *sync.Cond // おしらせの既読を監視するCond
addAnnouncementCond *sync.Cond // おしらせの追加を監視するCond
rmu sync.RWMutex

registeredSchedule [5][6]*Course // 空きコマ管理[DayOfWeek:5][Period:6]
registeringCount int
scheduleMutex sync.RWMutex
scheduleCond *sync.Cond // スケジュールの空きを監視するCond
}
type AnnouncementStatus struct {
Announcement *Announcement
Expand All @@ -55,6 +56,7 @@ func NewStudent(userData *UserAccount, baseURL *url.URL) *Student {
}
s.readAnnouncementCond = sync.NewCond(&s.rmu)
s.addAnnouncementCond = sync.NewCond(&s.rmu)
s.scheduleCond = sync.NewCond(&s.scheduleMutex)
return s
}

Expand Down Expand Up @@ -253,6 +255,7 @@ func (s *Student) ReleaseTimeslot(dayOfWeek, period int) {

s.registeredSchedule[dayOfWeek][period] = nil
s.registeringCount--
s.scheduleCond.Broadcast()
}

func (s *Student) Courses() []*Course {
Expand All @@ -272,6 +275,31 @@ func (s *Student) RegisteredSchedule() [5][6]*Course {
return s.registeredSchedule
}

func (s *Student) WaitReleaseTimeslot(ctx context.Context, cancel context.CancelFunc, registerCourseLimit int) <-chan struct{} {
go func() {
select {
case <-ctx.Done():
case <-s.waitReleaseTimeslot(registerCourseLimit):
}
cancel()
}()
return ctx.Done()
}

func (s *Student) waitReleaseTimeslot(registerCourseLimit int) <-chan struct{} {
ch := make(chan struct{})
// MEMO: このgoroutineはWaitReleaseTimeslotがctx.Done()で抜けた場合放置される
go func() {
s.scheduleCond.L.Lock()
for s.registeringCount >= registerCourseLimit {
s.scheduleCond.Wait()
}
s.scheduleCond.L.Unlock()
close(ch)
}()
return ch
}

func (s *Student) GPA() float64 {
s.rmu.RLock()
defer s.rmu.RUnlock()
Expand Down
81 changes: 38 additions & 43 deletions benchmarker/scenario/load.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -183,38 +183,38 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.
return func(ctx context.Context) {
for ctx.Err() == nil {

if student.RegisteringCount() >= registerCourseLimitPerStudent {
// gradeはTimeSlotの空きが発生したらリクエストを送る
_ctx, cancel := context.WithDeadline(ctx, s.loadRequestEndTime)
<-student.WaitReleaseTimeslot(_ctx, cancel, registerCourseLimitPerStudent)
}

// grade と search が早くなりすぎると科目登録が1つずつしか発生せずブレが発生する
timer := time.After(100 * time.Millisecond)

if s.isNoRequestTime(ctx) {
return
}

timer := time.After(50 * time.Millisecond)
// 学生は成績を確認し続ける
expected := collectVerifyGradesData(student)
_, getGradeRes, err := GetGradeAction(ctx, student.Agent)
if err != nil {
step.AddError(err)
time.Sleep(1 * time.Millisecond)
continue
}
err = verifyGrades(expected, &getGradeRes)
if err != nil {
step.AddError(err)
} else {
step.AddScore(score.GetGrades)
// 履修したコースが0なら成績確認をしない
if len(student.Courses()) != 0 {
// 成績確認
expected := collectVerifyGradesData(student)
_, getGradeRes, err := GetGradeAction(ctx, student.Agent)
if err != nil {
step.AddError(err)
time.Sleep(1 * time.Millisecond)
continue
}
err = verifyGrades(expected, &getGradeRes)
if err != nil {
step.AddError(err)
} else {
step.AddScore(score.GetGrades)
}
}

// ----------------------------------------

// Gradeが早くなった時、常にCapacityが0だとGradeを効率的に回せるようになって点数が高くなるという不正ができるかもしれない
remainingRegistrationCapacity := registerCourseLimitPerStudent - student.RegisteringCount()
if remainingRegistrationCapacity == 0 {
// gradeのループは最低50ms間隔とする
DebugLogger.Printf("[履修スキップ（空きコマ不足)] code: %v, name: %v", student.Code, student.Name)
<-timer
continue
}

registerStart := time.Now()
{
var checkTargetID string
var nextPathParam string // 次にアクセスする検索一覧のページ
Expand All @@ -232,12 +232,10 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.
hres, res, err := SearchCourseAction(ctx, student.Agent, param, nextPathParam)
if err != nil {
step.AddError(err)
<-timer
continue
}
if err := verifySearchCourseResults(res, param); err != nil {
step.AddError(err)
<-timer
continue
}
step.AddScore(score.SearchCourses)
Expand All @@ -260,7 +258,6 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.
_, res, err := GetCourseDetailAction(ctx, student.Agent, checkTargetID)
if err != nil {
step.AddError(err)
<-timer
continue
}
expected, exists := s.CourseManager.GetCourseByID(res.ID.String())
Expand Down Expand Up @@ -288,7 +285,6 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.
_, getRegisteredCoursesRes, err := GetRegisteredCoursesAction(ctx, student.Agent)
if err != nil {
step.AddError(err)
<-timer
continue
}
if err := verifyRegisteredCourses(getRegisteredCoursesRes, registeredSchedule); err != nil {
Expand All @@ -299,8 +295,17 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.

// ----------------------------------------

// 仮登録
// grade と search が早くなりすぎると科目登録が1つずつしか発生せずブレが発生する
// あまりにも早い場合はここでMAX100ms待つ
<-timer

// 仮登録
remainingRegistrationCapacity := registerCourseLimitPerStudent - student.RegisteringCount()
if remainingRegistrationCapacity == 0 {
// unreachable
DebugLogger.Printf("[履修スキップ（空きコマ不足)] code: %v, name: %v", student.Code, student.Name)
continue
}
temporaryReservedCourses := s.CourseManager.ReserveCoursesForStudent(student, remainingRegistrationCapacity)

if s.isNoRequestTime(ctx) {
Expand All @@ -311,8 +316,8 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.

// ベンチ内で仮登録できた科目があればAPIに登録処理を投げる
if len(temporaryReservedCourses) == 0 {
// unreachable
DebugLogger.Printf("[履修スキップ（空き科目不足)] code: %v, name: %v", student.Code, student.Name)
<-timer
continue
}

Expand Down Expand Up @@ -345,15 +350,14 @@ func (s *Scenario) registrationScenario(student *model.Student, step *isucandar.
step.AddScore(score.RegisterCourses)
}
for _, c := range temporaryReservedCourses {
step.AddScore(score.RegisterCourseByStudent)
c.CommitReservation(student)
student.AddCourse(c)
c.StartTimer(waitCourseFullTimeout)
}
}

s.debugData.AddInt("registrationTime", time.Since(registerStart).Milliseconds())
DebugLogger.Printf("[履修完了] code: %v, time: %d ms, register count: %d", student.Code, time.Since(registerStart).Milliseconds(), len(temporaryReservedCourses))
<-timer
DebugLogger.Printf("[履修完了] code: %v, register count: %d", student.Code, len(temporaryReservedCourses))
}
// TODO: できれば登録に失敗した科目を抜いて再度登録する
}
Expand Down Expand Up @@ -451,15 +455,6 @@ func (s *Scenario) readAnnouncementScenario(student *model.Student, step *isucan

// 50msより短い間隔で一覧取得をしない
<-timer

endTimeDuration := s.loadRequestEndTime.Sub(time.Now())
select {
case <-ctx.Done():
return
case <-time.After(endTimeDuration):
return
default:
}
}
}
}
Expand Down
4 changes: 4 additions & 0 deletions benchmarker/scenario/prepare.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,10 @@ func (s *Scenario) Prepare(ctx context.Context, step *isucandar.BenchmarkStep) e
}
s.language = res.Language

if s.NoPrepare {
return nil
}

err = s.prepareNormal(ctx, step)
if err != nil {
return failure.NewError(fails.ErrCritical, err)
Expand Down
9 changes: 5 additions & 4 deletions benchmarker/scenario/scenario.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,10 +38,11 @@ type Scenario struct {
}

type Config struct {
BaseURL *url.URL
UseTLS bool
NoLoad bool
IsDebug bool
BaseURL *url.URL
UseTLS bool
NoLoad bool
NoPrepare bool
IsDebug bool
}

func NewScenario(config *Config) (*Scenario, error) {
Expand Down
2 changes: 2 additions & 0 deletions benchmarker/score/tags.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ const (
RegisterScore score.ScoreTag = "_15.RegisterScore"
AddAnnouncement score.ScoreTag = "_16.AddAnnouncement"
GetAnnouncementsDetail score.ScoreTag = "_17.GetAnnouncementDetail"
RegisterCourseByStudent score.ScoreTag = "_18.RegisterCourseByStudent"

StartCourseOver50 score.ScoreTag = "!01.StartCourseOver50"
)
Expand All @@ -50,6 +51,7 @@ var Tags = []score.ScoreTag{
RegisterScore,
AddAnnouncement,
GetAnnouncementsDetail,
RegisterCourseByStudent,

StartCourseOver50,
}
Expand Down

0 comments on commit 33bf24c

Please sign in to comment.